Skip to content

A partially-fulfilled AssignAgents chunk is treated as complete, so agents still starting get re-placed onto other nodes #3750

Description

@erdtsieck

Problem

An AssignAgents chunk is treated as fully delivered as soon as any reply arrives, but the reply only
carries the agents that finished starting inside the window. The remainder — agents that are still starting —
is neither confirmed nor held, so the next evaluation re-places them on a different node. With slow agent
starts the cluster spends its time shuffling agents between nodes instead of placing the thousands that have
never been placed at all.

AssignAgents.ExecuteAsync (StartAgents.cs:160-169):

var response = await runtime.Agents.InvokeAsync<AgentsStarted>(Destination, startAgents, timeout);
if (response == null) return AgentCommands.Empty;
runtime.Logger.LogInformation("Successfully started agents {Agents} on node {NodeNumber}", AgentIds, …);

AgentIds is logged as if all of it succeeded; response.AgentUris is never compared against it. And
StartAgents.ExecuteAsync only adds an agent to its successful bag once StartLocallyAsync returns, so a
chunk of 400 in which 100 finish inside the window replies with 100 and the other 300 are silently dropped
from the ledger when the dispatcher's release() runs in its finally. From there
EvaluateAssignments.cs:209 sees !isOutstanding, the TTL expires, and the agent is re-decided from scratch —
as a stop-then-start onto some other node, while it is still coming up on the first one.

Evidence

Counting AgentStarted records per agent over twelve minutes on an otherwise healthy five-node cluster (no
lane errors, no failed starts, no connection errors):

times started agents of which on more than one node
6 3 3
5 6 6
4 20 20
3 47 47
2 293 293
1 533 0

369 of 902 distinct agents were started more than once, every repeat on a different node — while roughly
5,600 agents that had never been placed sat waiting.

The churn is visible in the totals too: 432 AgentStarted against 320 AgentStopped in a single minute, and
a net trajectory that goes sideways with dips — 657 → 544 → 519 → 575 → 704 → 792 → 784 → 810 → 814 → 912 →
1,208 over fifteen minutes, against ~6,487 agents to place.

This was measured with AgentStartBatchSize and MaxAgentStartParallelism both at 400, which removes the
chunk timeouts entirely (12 confirmations, 0 lane errors — see #3748). So this is not a symptom of the
timeouts; it survives them being fixed.

Operationally: this is what makes a rolling deploy carrying a projection version bump unable to converge.
The bump makes every first start a multi-minute replay, and rolling pods is what forces agents to be placed
and moved while that runs. A deploy without a version bump is fine: production — which this canary is a restored copy of, same shape, same 512 tenant databases, same
~6,485 agents — sits fully converged at 1,301 / 1,301 / 1,295 / 1,294 / 1,294 across five nodes, with no
version bump in flight.

Suggested fix

  1. Compare the reply against the request. response.AgentUris is the set that actually started; the
    difference is the set still in flight. Keep that remainder pending rather than releasing it for
    re-placement, and log a warning — today the log claims unconditional success for the whole chunk.
  2. Prefer re-issuing an unconfirmed agent to the same destination. An agent that was dispatched and has
    not reported yet is most likely mid-start there; moving it costs the work already done and, with
    stop-then-start, can stop a copy that was about to become healthy.

Environment

Wolverine 6.24.2 / Marten 9.22.0 / JasperFx 2.36.3, .NET 10, 5 pods, DurabilityMode.Balanced with
UseWolverineManagedEventSubscriptionDistribution, database control queue, one Marten store over 512
tenant databases, ~6,487 agents (5,972 advertised capabilities per node + ~514 durability agents).

Starts are slow because a bumped projection version puts each shard behind #480's side-effect gate — a
bounded replay with a 5-minute ceiling. By contrast, production — which this canary is a restored copy of, same shape, same 512 tenant databases, same
~6,485 agents — sits fully converged at 1,301 / 1,301 / 1,295 / 1,294 / 1,294 across five nodes, with no
version bump in flight, so agents finishing inside the window is the normal case and this only
bites when they do not.

-- agents started more than once, and whether they moved node
with s as (
  select description as agent, count(*) as n, count(distinct node_number) as nodes
  from wolverine_node_records
  where event_name = 'AgentStarted' and "timestamp" > now() - interval '12 minutes'
  group by 1)
select n as times_started, count(*) as agents, sum((nodes > 1)::int) as on_multiple_nodes
from s group by 1 order by 1 desc;

Related

Same investigation, independent fixes: #3748 (acknowledgements wait for the agent work to finish, so
commands time out) and #3749 (a stop aimed at the source blocks the destination's lane). This one is what
remains once those two are addressed.

The root cause of the slow starts and stops this defect needs is JasperFx/jasperfx#594 — the side-effect gate
replays synchronously inside the agent start path. Fixing that removes the precondition; fixing this makes the
precondition survivable.

The outcome-level report is #3753 — "node assignment is very slow, or never completes, when a release
contains a projection version bump." This issue is one of the contributing causes; that one is the requirement.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

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