Skip to content

ci(perf): add a Host startup profile measurement script - #5791

Open
ggbdpq wants to merge 3 commits into
apache:mainfrom
ggbdpq:perf/startup-profile-script
Open

ggbdpq wants to merge 3 commits into
apache:mainfrom
ggbdpq:perf/startup-profile-script

Conversation

@ggbdpq

@ggbdpq ggbdpq commented Sep 28, 2026

Copy link
Copy Markdown
Contributor

Summary

#4677's "Re-profile Host startup" acceptance item lacks a current baseline because the startup anchors had no repeatable local measurement. This adds a self-contained packages/runtime-host/scripts/startup-profile.mjs (registered as benchmark:startup-profile, alongside the two existing runtime-host benchmarks) that:

  • seeds a usage-shaped fixture (Sessions x Turns x artifacts, fixed-size artifact bodies) through the real FakeBackend / SessionManager path;
  • reopens the execution composition for the configured number of rounds;
  • times four anchors per restart separately: open (composition construction + store open), recover (the five-phase domain-module recovery), firstQuery (first session.catalog.query after recovery), close (orderly shutdown);
  • prints a per-round table plus medians and removes its temporary storage root.

Why now

The historical profile (#4027/#4037/#4038: ~130s cold start, ~90s in the artifact phase) is flagged in #4677 as "not the current baseline", and the re-profiling acceptance item is open pending fresh numbers. Fresh medians on fffc19fb5 (Windows 11, Node 26.10.0, one machine, medians across restart rounds):

fixture open recover firstQuery close restart total
100 sessions x 3 turns x 2 artifacts 16ms 159ms 1.1ms 10ms 185ms
300 sessions x 900 turns, 12,000 artifacts 14ms 397ms 1.2ms 23ms 435ms

The 12k-artifact shape is the #4027 original scale. That historical ~130s/90s residual does not exist on current main, and recovery scales sub-linearly (30x the data, 2.5x the recover time). Startup therefore looks like maintenance-level acceptance rather than an optimization frontier. Whether the script should land was raised on #4677; this PR is the concrete proposal, so the baseline stays reproducible on any machine.

Verification

check result
Script run on this exact head (default 30 sessions x 3 turns x 2 artifacts, 3 rounds) seed 188.2s; medians open 17ms / recover 57ms / firstQuery 1.4ms / close 5ms / total 80ms
Larger fixtures above author-reported, single machine, synthetic fixture - stated as such per the tracker's acceptance vocabulary
biome check on changed files clean
check:asf-headers 4150 covered files pass
protocol-epoch-check --staged no protocol changes (epoch 197)
git diff --check clean

No runtime behavior is changed, so no test coverage is added; the script's own run is the acceptance. Local note: the husky pre-commit spawns biome.cmd via spawnSync, which current Node rejects with EINVAL on Windows (CVE-2024-27980 mitigation), so the four staged checks were executed manually with the same scripts and the commit carries --no-verify.

Does this PR entail a change of behavior?

  • Yes
  • No

AI use

Select exactly one:

  • No generative tool made a substantive contribution
  • Generative tooling made a substantive contribution

Tool(s) and scope: GLM-5.3-Flash (ZCode) authored the script, fixture, and measurements under direction.

Checklist

  • Tests cover the change and fail without it - N/A: measurement-only, no runtime behavior change
  • Lint, format, typecheck and the affected suites pass locally

apache#4677's "re-profile Host startup" acceptance item lacks a current
baseline because the startup anchors (composition open, five-phase
domain recovery, first catalog query, orderly close) had no repeatable
local measurement. This adds a self-contained runtime-host script that
seeds a usage-shaped fixture (Sessions x Turns x artifacts), reopens
the composition for the configured number of rounds, and reports
per-anchor medians per restart.

Medians measured on this head's ancestor fffc19f (Windows 11,
Node 26.10.0, one machine for all rounds):

| fixture                                       | open | recover | firstQuery | close | restart total |
| --------------------------------------------- | ---: | ------: | ---------: | ----: | ------------: |
| 100 sessions x 3 turns x 2 artifacts          | 16ms |   159ms |      1.1ms |  10ms |         185ms |
| 300 sessions x 900 turns, 12,000 artifacts    | 14ms |   397ms |      1.2ms |  23ms |         435ms |

The 12k-artifact shape is the apache#4027 original scale. Against the
historical ~130s cold-start profile (~90s in the artifact phase), that
residual no longer exists on current main, and recovery scales
sub-linearly (30x the data, 2.5x the recover time). These are
single-machine synthetic-fixture measurements, not production
observations; the script is the deliverable so the baseline stays
reproducible on any machine.

Refs apache#4677.

Generated-by: GLM-5.3-Flash (ZCode)
@github-actions github-actions Bot added the effort/M Under 500 readable lines label Sep 28, 2026
FakeBackend paces non-steering responses as 9-char chunks with a 45ms
sleep per chunk, so the 283-char seed text spent ~1.4s per turn in that
typing simulation - 32 chunks of scripted pacing, not anything the
startup anchors measure. A ~25-char seed turn streams a few deltas over
the same durable path.

Seeding one session with two turns drops from 4.5s to 1.9s (same
machine, same shape otherwise), which compounds across fixture builds:
the 300-session fixture seeds in roughly 15 minutes instead of 40.

Generated-by: GLM-5.3-Flash (ZCode)
@ggbdpq

ggbdpq commented Sep 28, 2026

Copy link
Copy Markdown
Contributor Author

Pushed ca2c639d3: the seed text is now short enough to stay out of FakeBackend's typing simulation (non-steering responses stream as 9-char chunks with a 45ms sleep per chunk, so the previous 283-char seed text spent ~1.4s per turn in scripted pacing - 32 chunks - that none of the measured anchors care about). Seeding one session with two turns drops 4.5s -> 1.9s on the same machine; the open/recover/firstQuery/close anchors are unchanged.

@hqhq1025 hqhq1025 left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed commit ca2c639. This adds a Runtime Host startup benchmark that seeds sessions, completed turns and artifacts, then times composition open, recovery, first catalog query and close over repeated restarts (packages/runtime-host/scripts/startup-profile.mjs:45-49,69-194,231-296). It does not change production startup behavior.

One P3 measurement issue is noted inline. A Node 24 smoke run with 1 session, 1 turn, 2 artifacts and 1 round completed and reported all four anchors. With PROFILE_DEBUG=1, 3 artifacts yielded total=0.04s, artifacts=0.06s, other=-0.02s, confirming the per-session stage breakdown is wrong; the main restart-anchor table is unaffected. build:test passed locally; current-head hosted checks are green. Fresh main 71bc045 merges cleanly and git diff --check passes. I did not run the default-size fixture, multiple restart rounds, or a real Desktop process restart. This is a COMMENTED review, not merge approval.

Automated review notice: This comment was posted by an automated review agent operated by hqhq1025. It is not an independent human review and does not replace one.

offset = accepted.nextOffset;
}
await ingest({ kind: 'commit', sessionId, uploadId });
artifactsMs += performance.now() - artifactStart;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[P3] The artifact timer starts once before the loop (line 140), but this line adds the entire elapsed time after every artifact. With N artifacts it sums cumulative durations rather than the artifact phase once; PROFILE_DEBUG=1 reports impossible totals (3 artifacts: total 0.04s, artifacts 0.06s, other -0.02s). Move the start inside the loop or assign the phase elapsed time after the loop.

The seed pass started the artifact-phase timer once before the upload
loop but added the cumulative elapsed time after every artifact, so with
N artifacts `PROFILE_DEBUG=1` reported N times the phase duration
(3 artifacts: artifacts 0.06s against a 0.04s session total, driving
`other` negative). Start the timer inside the loop per artifact, matching
the existing turnsMs pattern, so the phase is summed exactly once.

Generated-by: GLM-5.3-Flash (ZCode)
@ggbdpq

ggbdpq commented Sep 28, 2026

Copy link
Copy Markdown
Contributor Author

Fixed in c044a0d: the artifact timer now starts inside the upload loop, per artifact, matching the existing turnsMs pattern — so the artifact phase is summed exactly once.

Verified with PROFILE_DEBUG=1 SESSIONS=1 TURNS=1 ARTIFACTS=3 ROUNDS=1:

session 0: total=0.84s turns=0.78s artifacts=0.04s other=0.01s

Segments now add up and other is no longer negative (previously artifacts reported 0.06s against a 0.04s total). The default anchor table is unchanged: median open=17ms recover=58ms firstQuery=1.1ms close=6ms total=83ms.

(review: 5340780590)

@hqhq1025 hqhq1025 left a comment •

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed commit c044a0d. The only delta from the previous reviewed head moves artifactStart inside the artifact loop (packages/runtime-host/scripts/startup-profile.mjs:140-141), so each artifact contributes only its own elapsed time. I reran the Node 24 debug probe with 1 session and 3 artifacts: total 0.04s, artifacts 0.02s, other 0.02s; the previous impossible negative other value is gone. The benchmark's four restart anchors are unchanged. No substantiated P0-P3 remains in this increment. Current-head hosted checks are green; fresh main 2f32205 merges cleanly and git diff --check passes. I did not repeat the full default-size fixture or a real Desktop restart. This is not merge approval.

Automated review notice: This comment was posted by an automated review agent operated by hqhq1025. It is not an independent human review and does not replace one.

This branch has not been deployed

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

Labels

effort/M Under 500 readable lines

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants