Skip to content

Root cause: the blue/green side-effect gate replays synchronously inside the agent start path, with a hard-coded 5-minute ceiling (follow-up to #480) #594

Description

@erdtsieck

This is the root cause of a cluster of problems we hit today, and the other three are consequences of it.
Each of JasperFx/wolverine#3748, #3749 and #3750 needs slow agent starts and stops as its precondition.
This gate is what makes them slow: it turns a shard's first start on a bumped projection version from
milliseconds into 27s at p50 and 215s at the tail. Fix this and the precondition disappears; fix the other
three and the precondition becomes survivable. We would like both, but this is the one that would let us
deploy a version bump at all.

Follow-up to #480, which we asked for and have now run at scale. The gate does what it should; the problem is
where it runs.

Problem

tryApplySideEffectVersionGateAsync performs the warm-up replay synchronously inside the agent start path,
before the continuous agent is started, bounded by a hard-coded ceiling:

private static readonly TimeSpan SideEffectGateTimeout = 5.Minutes();   // JasperFxAsyncDaemon.cs:420await rebuildAgent(warmup, prior, SideEffectGateTimeout, floor: current, disableOptimizedReplay: true);

So starting a shard on a bumped projection version blocks for as long as the replay takes, and if it exceeds
five minutes the start fails and the shard is left stopped.

Measured on our canary — one Marten store over 512 tenant databases, 993 tenants, one projection bumped to a
new version — the warm-up durations over a 25-minute window, taken from the paired
is behind the prior version's progression / finished its side-effect-suppressed warm-up log lines:

completed still running min p50 p95 max
42 31 1.1s 27.3s 81.8s 214.8s

Tens of seconds is the normal case and minutes is not rare, all of it inside a start.

A timeout is also not the same as a failure. We had provided-cares:V23 for tenant 01057869 fail its
start three times on SideEffectGateTimeout, while the shard's progression sat at exactly its high-water mark
(899979) — the replay had finished; only the wait expired. Each retry then re-ran a warm-up that had nothing
left to do.

Throughput, and a concurrency cap we cannot find

The durations above are only half of it. Measured across all five pods since start, over a 10.3-minute window
with one projection bumped over 993 tenant shards:

warm-ups started finished rate peak concurrency remaining
96 49 4.7 / min 60 ~944 of 993

At 4.7 per minute that is ~200 minutes of replay before every shard has started once — and that is the floor
of the deploy, independent of anything the distribution layer does.

The peak concurrency of 60 is not a cap — I checked MaxConcurrentRebuilds / _rebuildBudget and it is a
per-daemon semaphore, and a multi-database store runs one daemon per database, so it does not throttle across
512 of them. 60 is simply how many gate-needing shards happen to fall in one in-flight chunk: 993 of the 5,972
advertised agents are shards of the bumped projection, so a chunk of 400 carries ~66 of them.

That is the point, though. Warm-up concurrency is not something an operator can size — it is a side effect of
how the distribution layer happens to chunk agents, and of how many agents of the bumped projection land in the
chunk that is currently in flight. A dedicated concurrency control for the warm-ups themselves, independent of
agent-start batching, would make the floor predictable and tunable rather than emergent.

Projection batch size is not a lever we can find — and the duration varies wildly between windows

The obvious thing to try from our side was the projection's own AsyncOptions.BatchSize (ours is 200 at
registration, deliberately below Marten's 500 because a composite fans one batch out over a dozen member
projections). I measured three windows and have to report the result as inconclusive rather than as a finding:

projection BatchSize window p50 p95 max warm-ups/min
200 25 min 27.3s 81.8s 214.8s 4.7
1000 10 min 23.8s 234.5s 268.0s 3.1
200 (reverted) 7.6 min 32.1s 156.9s 288.5s 3.1

The same nominal configuration produced a p95 of 82s in one window and 157s in another, so the
window-to-window variance is larger than any effect I could attribute to the batch size. The likely reason is
composition: which tenants happen to be warming up dominates, and their backlogs differ by more than an order
of magnitude (60k to 900k events per tenant here). So batch size is not a workaround we can lean on, but I
cannot claim it makes things worse either.

What is robust across every window: warm-ups take tens of seconds at the median and multiple minutes at the
tail, and in the last window the maximum reached 288.5s against the 300s ceiling — twelve seconds of
headroom. At that point start failures are not a tail risk, they are the next sample.

Why it matters beyond the gate

Under Wolverine-managed event subscription distribution, agent start and stop durations feed straight into the
cluster's command acknowledgement windows. A start that takes minutes blows them, and we could not converge a
five-node, ~6,500-agent cluster at all: JasperFx/wolverine#3748, #3749 and #3750. Practically, a rolling
deploy that carries a projection version bump cannot converge
— a deploy without one is fine.

We worked around it on the Wolverine side by deriving batch and parallelism from the measured durations above
(both 400, giving a 430s reply window that covers the 215s max) plus a raised pending-ledger TTL. That took us
from 591 agents placed and flat to 2,457 spread evenly. It is a workaround an operator has to reverse-engineer
from three source files, and it would not be needed if a start returned promptly.

Suggested fix

  1. Do not do the warm-up inside the start path. Start the agent in a side-effects-suppressed mode and let
    the normal shard execution carry it to the prior version's mark, then flip to full execution. The gate's
    purpose is a property of a running agent, and the replay already resumes from its own persisted progress,
    so nothing needs to block a start.
  2. Re-check progression before treating a timeout as a failure. If the shard has reached prior, the
    warm-up succeeded regardless of the clock.
  3. Make the ceiling configurable. Five minutes hard-coded cannot suit both a small store and 512 databases.
  4. Leave a failed warm-up paused-and-resumable rather than stopped, so it recovers without operator action.

Environment

JasperFx 2.36.3 / Marten 9.22.0 / Wolverine 6.24.2, .NET 10, DurabilityMode.Balanced with
UseWolverineManagedEventSubscriptionDistribution, one Marten store over 512 tenant databases with
Events.UseTenantPartitionedEvents, ~6,500 agents. Canary on a restored production copy, so we can reproduce
at full scale and iterate quickly — happy to run whatever would be useful.

The outcome-level report is JasperFx/wolverine#3753 — "node assignment is very slow, or never completes,
when a release contains a projection version bump." This issue is what I believe is the root cause of it.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions