Joining a team with real history takes hours and ends unreadable: 17,300 messages, 4+ hours, empty roster, 4,100 blocked

[fujibee]

Joining a team with real history is not slow — it is unusable. Measured on agmsg 1.2.2 against a team with 17,300 messages: agmsg-cloud sync <team> ran for over four hours, and what the user got at the end was a team they could not read.

End state after 4+ hours

sync_quarantine  imported             13,200   seq 1-13,200
sync_quarantine  unsupported_cipher    4,100   seq 13,201-17,300
messages                              13,170
sync_read_members                          0   <- roster is empty

So: four hours, 4,100 messages unreadable, and no roster at all.

The cost is linear in history, and dev never sees it

Measured throughput: 5 messages/second, the same for both the apply pass and the reprocess pass. One join costs roughly history x 200ms x 2 passes.

     50 messages   ->  10 seconds     (nothing to notice while developing)
 17,300 messages   ->  4 hours        (only appears against real data)

That ratio is the reason this survived: every development-sized team is fast.

Known cost centres

Some of these are measured, some are not. Listed so the work can be split, not because all of them are established causes.

• Process spawn per message — measured (Applying a pull page spawns 34 processes per message, and the quoting helper is 32 of them #908). 34 processes per message on the apply path, 32 of which are printf|sed forks in the quoting helper. Benchmarked at 32x1000 calls: 127 seconds, against 0.131 seconds for the equivalent bash expansion.
• Reconcile gap detection — reconcile's gap detection is a correlated subquery evaluated per candidate — quadratic on large histories #912. Correlated subquery evaluated per candidate; with 16,640 candidate rows it does not finish in 400 seconds.
• Push throughput — Push cost is per-message, not per-byte: one age fork per message and six processes per ACK row #913. 2.5MB took 359 seconds on a link that sustains 11MB/s. Established as per-message, not per-byte: one age fork per message, six processes per ACK row.
• The empty roster — The roster is written only by the engine after its pull drain, so a large join shows an empty roster for hours — and forever without the key #914. Traced: the roster is written only by the engine, as the last step after its own pull drain. pull-bootstrap never touches it, and a machine without the key never starts the engine. So on a large team the roster is always last, and without the key it never appears.
• The 4,100 blocked messages. They stop at unsupported_cipher at a clean boundary (seq 13,201). The reprocess that would clear them failed with exit 13 and no diagnostic — see storage_sync_prepare_push returns 13 with nothing on stdout or stderr #835, and An engine was running for a team that had just reported itself halted — starter unidentified #909 for what was running afterwards.

What this issue is for

The umbrella for "history-proportional join is broken", tracking the symptom end to end. Individual causes get their own numbers as they are established; this one stays open until a team of this size can be joined and read.

Related: #908 (spawn cost), #835 (exit 13 with no diagnostics), #909 (engine running under a halted team), #901 (join cannot tell a locked team from an empty one).

[fujibee]

The four hours, split

Two independent measurements now account for the total, and the harness was never missing 3.5x — it was measuring one of the two stages.

pull-bootstrap   03:27:27 -> 04:26:18   3,531 s / 17,300 msgs =  204 ms/msg
reprocess        04:26:18 -> ~07:51:51 12,333 s / 13,200 msgs =  934 ms/msg
                                        total 4.41 h

The harness measures the pull only, and reports 227-286 ms/msg on a loaded machine. That matches the 204 ms/msg the real pull-bootstrap did. The pull was reproduced all along.

What the harness does not run is the second stage, and that stage is both longer (3h25m against 59m) and 4.5x more expensive per message (934 against 204 ms). It also never finished: it processed 13,200 of 17,300 and then died, leaving 4,100 quarantined.

The reprocess end time is taken from the engine log — the failure was printed before 07:52:16 — so it is accurate to within a minute, not to the second.

What this changes

The earlier framing in this issue treated "join takes four hours" as one cost. It is two, with different rates and different causes, and the expensive one is the one no harness covers yet (#916).

It also means the per-message apply cost is not superlinear: a 17,300-message run measured page by page shows a flat per-page cost with the store grown to 10,000 rows, and the one slow stretch tracked a machine load spike and recovered. Whatever makes reprocess 4.5x dearer than pull is a property of the reprocess path, not of history size.

Related: #916 (the uncovered stage), #919 (the lock that killed this reprocess), #909.

[fujibee]

The pull is linear, and dev-size predicts prod-size

The 17,300-message join finished on the harness:

bootstrap.apply   4,507 s / 17,303 msgs = 260.5 ms/msg     total wall 1.26 h
per page (1000)   286 274 272 273 308 322 246 241 227 235
                  264 255 251 251 240 243 246 74(303 msgs)
full pages        first 286 -> last 245   (drift x0.86, i.e. it got faster)
2,000 vs 17,300   x9 items -> x8 time

The two slow pages in the middle track a machine load spike and recover.

The projection made from 50 and 400 messages was 1.25 h. The measured result was 1.26 h. So the pull path has no superlinear term, and a development-sized run does predict the production-sized one — which was the open question behind "50 messages take 10 seconds and 17,300 take four hours".

The real machine's pull stage did 204 ms/msg in 59 minutes; the harness box is slower and loaded, and lands at the same shape.

What is left

The four hours were never one thing. The pull is an hour and behaves. Everything unexplained is in the reprocess stage — 934 ms/msg (#922), never finished, and covered by no harness (#916).

[fujibee]

Both endpoints of the reprocess window are measured now

The 934 ms/message figure was written above as if the reprocess had occupied the whole window from the key arriving to the failure. That was an assumption at the time. It has since been checked, and it holds:

remote.sh      cmd_unlock calls reprocess right after configure, nothing between
04:26:19Z      mtime of the file configure writes
04:26:25Z      mtime of roster.jsonl = the first reprocess page landing
history        one sync at 03:25:40Z, no manual unlock/reprocess after it
end            before 07:52:16Z, from the engine log

So 12,300 s / 13,200 messages = 930 ms/message is measured, accurate to about a minute. Detail on #922.

What remains unmeasurable on this artifact: the distribution of import times. No column in sync_*, events or messages carries a local write timestamp, so only the endpoints exist.