DurabilityAgent reads the whole assignment table once per database per poll: 76 calls and 772k rows a second at 512 databases

[erdtsieck]

Problem

DurabilityAgent's recovery timer needs the active node numbers to spot messages orphaned by a departed node:

var nodes = await _runtime.Storage.Nodes.LoadAllNodesAsync(_runtime.Cancellation);
activeNodeNumbers = nodes.Select(n => n.AssignedNodeNumber).ToList();

That is a per-node fact, but LoadAllNodesAsync also selects the entire assignment table so it can populate WolverineNode.ActiveAgents, which this caller never reads:

// PostgresqlNodePersistence.LoadAllNodesAsync
$"select {NodeColumns} from {_nodeTable};select {Id}, {NodeId}, {Started} from {_assignmentTable};"

And there is one durability agent per message database. So on a sharded deployment the query count scales with the database count, and the row count scales with the agent count.

Measured

A production cluster with 512 shard databases, five nodes, ~10,000 assigned agents, default ScheduledJobPollingTime of five seconds. All figures from the main message store:

calls of the assignments select	76 / second
rows returned from that one table	772,000 / second
calls since the stats were reset (128 days)	245,000,000
Client:ClientWrite	164 of 170 average active sessions
Lock:transactionid	0.04 AAS

pg_stat_statements shows the node select and the assignment select with identical call counts, which is the two-statement command above. So this is volume, not contention: the server spends its time writing those result sets back to the clients.

It also has a second-order effect. Each of those calls holds a pooled connection for its duration, which empties the pool (~4,000 pool has been exhausted an hour at a cap of 50). The heartbeat writes then time out at the 15s Npgsql timeout, the leader declares healthy nodes stale, and reassigning their agents churns the very table being read 76 times a second — 3,842 node records in ten minutes during one such episode.

Note that SqlServerNodePersistence already filters the equivalent read with where node_id = @id; the unfiltered pair is on the "load everything" path that this caller happens to use.

Suggested fix

The value is identical for every database on the node, so fetch it once per node per polling interval instead of once per database — the same reasoning as PersistenceMetricsSweeper for the metrics polling in GH-3375, whose doc comment describes this exact failure mode ("at high database counts the in-phase per-agent pollers each pinned a pooled connection").

The caller already tolerates data one interval old, since that is how often it looks, so behaviour is unchanged and the query count drops by the database count.

PR follows.

[erdtsieck]

Adding the full measurement set, since the arithmetic is the argument here.

The deployment

Sharded Marten/Wolverine, one message database per tenant group: 512 shard databases plus the main store, five API pods, DurabilityMode.Balanced, default ScheduledJobPollingTime of five seconds. wolverine_node_assignments currently holds 10,173 rows (roughly 850 tenants × 6 async projections, plus one durability agent per shard database), assigned across four of the five nodes.

The main store is a db.m8g.4xlarge with max_connections = 2400, shared with two other databases.

What the two queries cost

From pg_stat_statements on the main store, accumulated since 30-03 (3,066 hours):

statement	calls	rows/call	ms/call	total exec
select id, node_number, description, uri, started, health_check, version, capabilities from wolverine_nodes	244,934,608	3	13	3,237,589 s
select id, node_id, started from public.wolverine_node_assignments	244,934,532	4,523	10	2,386,349 s

The call counts are identical to within 76, which is the two-statement command in PostgresqlNodePersistence.LoadAllNodesAsync showing up as its two constituent statements. Average over that window: 23 calls/s and 100,374 rows/s.

Sampled over a 20-second window today, with the table at its current size:

75.9 calls/second
772,055 rows/second

That is ~245 million calls and, cumulatively, over a trillion rows returned from one small table since March.

Where the server's time goes

Performance Insights on the main store, one hour:

wait event	AAS
Client:ClientWrite	163.14
CPU	6.18
Timeout:VacuumTruncate	0.27
LWLock:BufferContent	0.10
Lock:transactionid	0.03

169.9 AAS total. Attributed per database: references_productie 163.91, the two co-tenant databases 5.95 combined. So it is not contention and it is not the query plan — the server spends its life writing those result sets back to clients. A pg_stat_activity snapshot agrees: 161 active sessions in Client/ClientWrite, 116 on the node select and 50 on the assignment select.

The second-order effect, which is what actually hurt

Each of those calls holds a pooled connection while the rows stream out. The main store's pool empties, and the failure surfaces inside ConnectAsync because the 15-second budget was consumed waiting for a slot:

Npgsql.NpgsqlException: The operation has timed out
 ---> System.TimeoutException
   at Npgsql.Util.NpgsqlTimeout.Check()
   at Npgsql.Internal.NpgsqlConnector.ConnectAsync(NpgsqlTimeout timeout, CancellationToken)

Per three minutes, from the pods: Error writing the heartbeat for node 16, Error trying to perform agent health checks, Error trying to remove the assignment of agent … in persistence, Error trying to run durability agent commands. The exhaustion messages themselves come almost entirely from Wolverine's own machinery — over one three-minute sample: IAgentCommand 72, DurabilityAgent 64, NodeAgentController 24, WolverineRuntime 22, DatabaseControlListener 6, DatabaseControlTransport 3.

From there it closes into a loop. A node whose heartbeat write times out is declared stale; its agents are reassigned; the reassignment rewrites the very table being read 76 times a second. Observed on one afternoon:

• a node re-registered under a new node number without its pod ever restarting (0 restarts, same pod name) and then held zero assignments while the other four carried 10,238
• 3,842 rows written to wolverine_node_records in ten minutes during one redistribution
• ProgressionOutOfOrder 131 times across 28 tenants in twelve hours, each one ending in Agent … is not running because of a failure it cannot recover from by restarting … It will be left alone until the underlying problem is resolved — i.e. projection agents permanently stopped until an operator intervenes
• database load tripled, 55 → 170 AAS, tracking the churn

Why this is a demand problem and not a pool-sizing problem

We raised the main store's pool cap from 20 → 50, then 50 → 100. The exhaustion count did not move: 94–156 per three minutes at cap 50, 181 per three minutes at cap 100, all reading 'Max Pool Size' (currently 100). A larger pool just buys more concurrent full-table reads. The occupancy is nowhere near the server's ceiling either — 306 connections of 2400 — so this is not a resource limit being hit, it is work that should not exist.

Why it scales the wrong way

The call rate is a function of the database count and the row count is a function of the agent count, and the caller only ever uses AssignedNodeNumber. We go from 644 to roughly 3,100 tenants over the next three weeks, so the assignment table grows by about the same factor — at an unchanged 76 calls/s that is on the order of 2.8 million rows a second out of one table, for a list of integers.

For contrast, SqlServerNodePersistence already narrows the equivalent read with where node_id = @id; it is the "load everything" path that this caller happens to sit on.

Note on severity

Since upgrading to 6.24.6 / 9.22.4 / 2.39.5 the user-visible damage has stopped: projections are fully caught up (0 of 3,878 shards behind), no agents have been abandoned since, and p95 is 0.28 s. The traffic in this issue is unchanged, though — it is pure waste that got dangerous when combined with anything else competing for the pool, and it will get proportionally worse as the fleet grows.

The fix in #3847 fetches the numbers once per node per polling interval instead of once per database, which on this deployment is roughly a hundredfold reduction, with no behaviour change: the caller already tolerates data one interval old, because that is how often it looks.