What happens
At supervisor start, one worker child is forked per department, all within about a second. Each then performs the same full package-catalog initialization independently. Done alone that costs ~11 s; done by 29 workers at once it costs ~141 s each. Until a worker finishes, the cron tick already sitting in its queue cannot be served, so the first useful work of a deployment happens about two and a half minutes after start.
Measured
Fork time comes from the child log filename's spawn epoch; first-work time from that child's own EVENT=code_provenance line. 448 children across three deployments, one run:
spawned within 30 s of supervisor start (29 children): median 141 s max 143 s
spawned more than 10 min after start (263 children): median 11 s max 89 s
The same initialization, 13x slower when it is done concurrently.
The burst itself, from the packages supervisor log — MSG=framework spawned, 19 distinct pids in one second:
15:52:25 1
15:52:26 19 <-- one per department
15:52:27 2
15:52:32 1
...
Independently confirmed by the child log filenames: 19 files carry spawn epoch 1787673146.
One of those 19, end to end:
15:52:26 forked (supervisor: framework spawned, pid 20501)
15:54:47 code_provenance first line the child emits, 141 s later
15:54:52 ENTRY queue=github-devloop-ops.devloop_observe_tick
Where the time goes
sample on a child in that state, 4322 samples, single thread, one path, every sample:
main → run → parse_args → PackageRoots::resolve_run → from_canonical
→ external_package_catalogs → UnitCatalog::discover → from_workspace_inner
→ build_indexes → build_own_module_indexes → scan_own_modules
→ scan_lua_modules → scan_lua_modules_inner
→ Path::canonicalize → realpath → __getattrlist 3905/4322 = 90%
Each child is handed --project-root plus 15 --package-root arguments; those roots hold 2140 .lua files between them, and scan_lua_modules_inner calls canonicalize once per file:
let logical = logical_module_name(root, &path, allow_root_init)?;
insert_path_entry(
modules,
logical,
path.canonicalize()
.with_context(|| format!("canonicalize {}", path.display()))?,
&format!("module root {}", root.display()),
)?;realpath resolves every component of every path, so the shared directory prefixes are re-resolved once per file, and then that whole effort is repeated in full by each of the other 18 workers.
The jitter is on the wrong thing
spawn_cron already staggers first fires deterministically:
let mut next = Instant::now() + cron_first_fire_jitter(&name, interval);
Recomputing that function over this deployment's 17 raisers (all intervals >= 300 s, so bound is the full 30 s) gives fires spread from 0.20 s to 28.41 s, at most 3 landing in any one second. That is working as designed.
But the ticks are not what stampedes. The workers are forked together regardless, and a jittered tick that arrives at +1.93 s waits behind a worker that will not be ready until +141 s. Spreading the ticks cannot help while the workers all initialize at once.
Two earlier reports on this, both wrong
I filed #413 claiming the scan was the cost because a sampled process was in it, and #415 claiming departments were killed by a stall watchdog because I read a delivery-age field as process lifetime. Both are closed, both were wrong on mechanism. #413 was closer than I gave it credit for when I retracted it: the retraction rested on a proxy scan of one root (1001 files) finishing in ~1.5 s, which understated the real scope (16 roots, 2140 files) and, more importantly, measured no startup stampede at all.
What is different here is that the claim is now a measured gap between two populations of the same system — 141 s against 11 s — rather than an inference from one stack.
What would close it
Either side would do, and they are independent:
- The per-file
canonicalize is the inner cost and repeats prefix resolution 2140 times per worker.
- 19 workers computing an identical catalog from identical inputs at the same moment is the multiplier. Nothing in the inputs differs between them.
The property to hold: bringing a deployment up should not cost every worker a full independent catalog build at the same instant, and a deployment's first tick should not wait minutes behind worker initialization.
What happens
At supervisor start, one worker child is forked per department, all within about a second. Each then performs the same full package-catalog initialization independently. Done alone that costs ~11 s; done by 29 workers at once it costs ~141 s each. Until a worker finishes, the cron tick already sitting in its queue cannot be served, so the first useful work of a deployment happens about two and a half minutes after start.
Measured
Fork time comes from the child log filename's spawn epoch; first-work time from that child's own
EVENT=code_provenanceline. 448 children across three deployments, one run:The same initialization, 13x slower when it is done concurrently.
The burst itself, from the
packagessupervisor log —MSG=framework spawned, 19 distinct pids in one second:Independently confirmed by the child log filenames: 19 files carry spawn epoch 1787673146.
One of those 19, end to end:
Where the time goes
sampleon a child in that state, 4322 samples, single thread, one path, every sample:Each child is handed
--project-rootplus 15--package-rootarguments; those roots hold 2140.luafiles between them, andscan_lua_modules_innercallscanonicalizeonce per file:realpathresolves every component of every path, so the shared directory prefixes are re-resolved once per file, and then that whole effort is repeated in full by each of the other 18 workers.The jitter is on the wrong thing
spawn_cronalready staggers first fires deterministically:Recomputing that function over this deployment's 17 raisers (all intervals >= 300 s, so
boundis the full 30 s) gives fires spread from 0.20 s to 28.41 s, at most 3 landing in any one second. That is working as designed.But the ticks are not what stampedes. The workers are forked together regardless, and a jittered tick that arrives at +1.93 s waits behind a worker that will not be ready until +141 s. Spreading the ticks cannot help while the workers all initialize at once.
Two earlier reports on this, both wrong
I filed #413 claiming the scan was the cost because a sampled process was in it, and #415 claiming departments were killed by a stall watchdog because I read a delivery-age field as process lifetime. Both are closed, both were wrong on mechanism. #413 was closer than I gave it credit for when I retracted it: the retraction rested on a proxy scan of one root (1001 files) finishing in ~1.5 s, which understated the real scope (16 roots, 2140 files) and, more importantly, measured no startup stampede at all.
What is different here is that the claim is now a measured gap between two populations of the same system — 141 s against 11 s — rather than an inference from one stack.
What would close it
Either side would do, and they are independent:
canonicalizeis the inner cost and repeats prefix resolution 2140 times per worker.The property to hold: bringing a deployment up should not cost every worker a full independent catalog build at the same instant, and a deployment's first tick should not wait minutes behind worker initialization.