Conversation
…t serial test parseLog measured each file as (next-header - this-header) but only matched the `--- [N/M] path` form. runner.node.mjs prints parallel-safe headers without the `--- ` prefix, so the last serial file on every shard absorbed the entire parallel phase (79.5s reported for a 4.8s test on build 79247). Match the header with or without `--- `, close the open span at the `--- Running N parallel-safe tests` / `--- End` group boundaries, clamp concurrent-phase spans (they are inter-dispatch deltas, not wall clock), and drop the retry backoff between a failure label and the next attempt. This matches the parseLog already used by scripts/update-test-durations.mjs. parseLog is now exported behind an import.meta.main guard so the new test/internal/ci-slowest-tests.test.ts can exercise it directly.
…ibling parsers Since #36175, runner.node.mjs also emits: --- napi prebuild: N addon(s), Xs --- [A-B/M] K files in parallel (Nx) [N/M] <path> (X.XXs) (bucket per-file summary) none of which match '^--- [N/M] <path>'. Close the open span on any '--- ' group header so the test preceding the bucket is not charged the whole bucket run, and read the inline '(X.XXs)' timing from bucket summary lines. buildkite-slow-tests.js and update-test-durations.mjs share the same header contract and get the same fix.
…ary path - flush the open span at end-of-log in all three parsers so a job killed or timed out mid-run still records the last file instead of dropping it - require a test-file extension in the parallel-bucket summary name, matching update-test-durations.mjs - assert toBe(500) for the clamped parallel-safe span (fixture is deterministic) and cover the truncated-log case
…update-test-durations.mjs Closing the open span on any '--- ' line also matched test stdout that slipped past pipeTestStdout's sanitiser: unified-diff '--- a/<file>' inside bun-patch.test.ts (under-counted by ~33% on build #86086) and '--- ps ---' / '--- logs ---' from test/docker/index.ts inside test/package.json (~58%). Limit the boundary to the startGroup titles runner.node.mjs actually emits and cover the false positives in the fixture. Export parseLog from update-test-durations.mjs behind an entrypoint check so the test can run the same fixture through the parser CI shard bin-packing consumes.
|
Warning Review limit reachedYour included review limit has been reached. You’re in a promotional period — use the checkbox below to run this review for free:
On-demand reviews are free for the next 28 days. After that, they cost $0.25 per reviewed file. How can I continue?Run this review now using the option above, or comment You can also wait for the limit to reset (next review available in 2 minutes), then comment An organization admin can change what happens after included review limits in Billing. How do review limits work?CodeRabbit enforces per-developer PR review limits within each organization. For paid Pro and Pro+ reviews, CodeRabbit uses a developer's included PR review attempts over the past 7 days to set the current hourly allowance. At typical activity levels, the full plan allowance applies. Higher sustained activity can lower the allowance until earlier attempts leave the 7-day window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: ASSERTIVE Plan: Pro Run ID: 📒 Files selected for processing (13)
WalkthroughChangesSlow-test timing and Docker readiness
Possibly related PRs
Comment |
|
Status: PR open, stacked on #35418; this PR's own change is commit 8ae8dd7. Reproduced on build #99854's raw logs ( Test: Revision 2 (after review): the ready line is produced by one CI: build #103988 on 8ae8dd7 is green apart from |
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
There was a problem hiding this comment.
I reviewed this PR and didn't find any bugs. Since it's stacked on #35418 (whose parseLog rewrite is included in this diff) and touches test/harness.ts alongside three CI-tooling scripts, a human look before landing would still be worthwhile.
What was reviewed:
describeWithContainerchange is additive: only appends(waited Nms)to an existing diagnostic line; timing is measured across theawait startPromise, not fromensure()kickoff.- All three parsers subtract per-attempt, clamp at 0, and reset
containerMson every span boundary; the multi-marker-per-line case (progress dot + ready line) still extracts the wait becausecontainerWaitLineis unanchored and matched on the post-APC body. update-test-durations.mjs:strict: falseonparseArgsand moving the!tokenexit inside the entrypoint guard are both required for the test import to work; verified nothing else runs at import time.- Fixture test uses
BUN_TEST_SERVICE_mysql_plainso it exercises the real harness path with no docker dependency.
Extended reasoning...
Overview
This PR (stacked on #35418) makes describeWithContainer in test/harness.ts report how long its beforeAll blocked on docker-compose start-up, and updates three Buildkite log parsers (scripts/ci-slowest-tests.ts, scripts/update-test-durations.mjs, scripts/buildkite-slow-tests.js) to subtract that wait from a test file's measured wall-clock. It also wraps the two scripts' CLI bodies in entrypoint guards so parseLog can be exported and unit-tested, adds a .claude skill doc line, and adds test/internal/ci-slowest-tests.test.ts + a fixture that drives the real describeWithContainer via the BUN_TEST_SERVICE_* env override.
Because it is stacked, the diff also carries #35418's rewrite of parseLog (phase-header allowlist, parallel-bucket inline timings, truncated-log handling, retry-backoff exclusion). The net diff is ~600 lines across 7 files.
Security risks
None. All changes are in dev-only CI tooling, test harness diagnostics, and internal tests. No runtime, native, or user-facing code is touched. The only external I/O is the pre-existing Buildkite API fetch, unchanged in behaviour.
Level of scrutiny
Low-to-medium. Nothing here ships in the bun binary; the blast radius of a parser bug is a mis-ranked slow-test report or a slightly off expected-durations.json. The test/harness.ts edit only changes a console.log string. That said, the diff is large and includes another PR's commits, so a human should confirm they're happy landing both together (or wait for #35418 to land and let this rebase down to cfedace as the description says).
Other factors
- Test coverage is thorough: one shared fixture modelled on real build #99854 shapes runs through all three parsers with exact-value
toEqualassertions, plus a subprocess test that spawnsbun teston a fixture file and checks the real harness output matchescontainerWaitLine. Thephase-header boundarytable test pins the header allowlist against both positive and negative cases (diff lines,--- ps ---). - Checked that
strict: falseand the relocated!tokenguard inupdate-test-durations.mjsare what make importing it from the test safe — without them, module-load time would either throw on the test runner's argv orprocess.exit(1). - The unanchored
containerWaitLineregex correctly handles the two-APC-markers-on-one-line case in all three parsers: the header/phase regexes are anchored tobodystart so they don't false-match, while the wait regex scans anywhere in the post-APC remainder. - The design choice to also subtract in
update-test-durations.mjs(which feeds shard packing) is explained convincingly in the description, but it does change whatexpected-durations.jsonwill contain going forward — worth a maintainer nod.
cfedace to
2a4d19b
Compare
robobun
changed the title
2a4d19b to
5b196da
Compare
There was a problem hiding this comment.
I reviewed this PR and didn't find any bugs. It's well-tested CI-tooling work (no src/ changes), but it's stacked on #35418 and deliberately changes what update-test-durations.mjs records — container waits now come off the file's cost before it lands in expected-durations.json, which feeds shard packing. That behaviour change and the moderately intricate parser state (bucket attribution, per-attempt wait accounting) are worth a human look.
What was reviewed:
awaitService()and thedescribeWithContainerrewiring — default-paramensure()is call-time, andbeforeAllmeasures only the block, not since kick-off.- All five direct
dockerCompose.ensure()callers converted; no remaining test-file callers. - Both
parseLogimplementations against the fixture: retry attempts resetcontainerMs, bucket waits keyed by the<path>:block header, floor-at-0 for skew, truncated-log close onlastTs. - Import-for-test guards:
strict:falseonparseArgs, token check moved inside the entrypoint guard,prestartMapimport is side-effect-free.
Extended reasoning...
Overview
Stacked on #35418; the combined diff touches 14 files entirely in scripts/, test/, and .claude/. The core change is a producer/consumer pair: awaitService() in test/docker/index.ts prints Container ready via docker-compose: ... (waited Nms) from the blocked test process, and the two log parsers (scripts/ci-slowest-tests.ts, scripts/update-test-durations.mjs) subtract that reported wait from the file's measured span. describeWithContainer and the five test files that called ensure() directly now go through awaitService(). A 383-line test file drives one fixture (built from real #99854/#99975 log shapes) through both parsers and spawns bun test on a fixture with BUN_TEST_SERVICE_mysql_plain set so the real producer output is checked against containerWaitLine on every lane without docker.
Security risks
None. No runtime code, no untrusted-input parsing that reaches production; the parsers consume BuildKite job logs in developer-run scripts. The five test-file edits are one-line ensure() → awaitService() swaps plus removal of now-redundant console.log lines.
Level of scrutiny
Medium. Nothing here ships in the binary, but update-test-durations.mjs writes test/expected-durations.json, which runner.node.mjs uses to bin-pack shards and (on the PR darwin lane) skip files expected to exceed 10 s. Recording container-backed files at their own cost instead of own+wait is the design decision the description flags; it breaks the feedback loop where a file's recorded wait determines its shard placement which determines its next recorded wait. The parser state machine (serial span, concurrent clamp, bucket <path>: attribution, per-attempt containerMs reset, floor-at-0) is the part that needed careful reading; the fixture in ci-slowest-tests.test.ts covers each of those shapes with exact expected values, and the spawn test ties the real producer output to the parsers' regex.
Other factors
- Stacked on #35418, which rewrites and exports
parseLog; this diff includes those commits because the base branch is ~560 commits behind. It cannot merge until #35418 lands. - The
import.meta.main/process.argv[1] === fileURLToPath(...)guards andstrict: falseonparseArgsexist so the test file can import the parsers without tripping the token check or unknown-arg rejection; verifiedprestart-map.mjsis a pure data export so the top-level import inci-slowest-tests.tsis side-effect-free when imported by the test. scripts/buildkite-slow-tests.jsis left as #35418 has it (caller-less; #37149 deletes it), matching what the earlier-revision review asked for.- No prior human review comments on the thread; coderabbit's run failed to post.
awaitService() in test/docker/index.ts wraps the wait for a service and prints "Container ready via docker-compose: <service> at <host>:<ports> (waited Nms)"; describeWithContainer and the five test files that call ensure() directly go through it. ci-slowest-tests.ts and update-test-durations.mjs take the waits reported inside a file's span off that file, and inside the parallel bucket attribute them through the "<path>:" block header bun prints before each file's output and take them off the file's summary figure. ci-slowest-tests.ts reports the waits in a separate column and lists the longest on stderr, tagging files missing from test/docker/prestart-map.mjs. Whichever file on a shard first touches a cold service otherwise has the container start inside its measured time: 36.9s for sql-statement-cache-hash-collision.test.ts on alpine in build #99854, 22.4s for regression/issue/24850.test.ts, 15-20s for several postgres files, all of which run in well under a second; update-test-durations.mjs then commits those numbers to test/expected-durations.json. The reported wait is the only usable signal: a file with several container describes runs real tests between its ready lines (sql-mysql.test.ts prints three, 4s apart, with every service already up), so neither line timestamp measures the wait.
5b196da to
8ae8dd7
Compare
There was a problem hiding this comment.
I reviewed this PR and didn't find any bugs. Because it's stacked on #35418 (whose parseLog rewrite is bundled into this diff), touches test/harness.ts (loaded by every test file), and changes the input to shard packing via update-test-durations.mjs, a human look is still worthwhile before landing.
What was reviewed:
awaitService()wrapsensure()and prints the timing line; the fiveensure()→awaitService()swaps and thedescribeWithContainerchange preserve behavior (same promise awaited, plus a console.log).- Both parsers' container-wait subtraction (serial spans, bucket
<path>:attribution, floor-at-0, per-attempt) checked against the fixture log;bucketWaitsis correctly deleted after use so a retry summary line isn't double-subtracted. strict: falseinparseArgsand moving the token check under theimport.metaguard lets the test importupdate-test-durations.mjswithout side effects.
Extended reasoning...
Overview
This PR (stacked on #35418) keeps docker-compose container start-up time out of per-file CI timings. It adds awaitService() in test/docker/index.ts that awaits a service and prints Container ready via docker-compose: ... (waited Nms); describeWithContainer in test/harness.ts and five direct ensure() callers now go through it. The two log parsers (scripts/ci-slowest-tests.ts, scripts/update-test-durations.mjs) subtract the reported wait from a file's measured span, with parallel-bucket attribution via bun's <path>: output block. ci:slowest reports waits in a new column and stderr list, tagging files missing from prestart-map.mjs. A new test/internal/ci-slowest-tests.test.ts (22 tests) covers both parsers and spawns a fixture that exercises the real describeWithContainer → awaitService output via BUN_TEST_SERVICE_mysql_plain.
The diff includes #35418's parseLog rewrite (exported for testing, phase-header allowlist, truncated-log handling), so ~half the visible parser churn belongs to the base PR.
Security risks
None. All changes are in CI tooling scripts, test infrastructure, and test files. No runtime code, no auth/crypto/permissions, no untrusted input handling beyond parsing Buildkite log lines with anchored regexes.
Level of scrutiny
Medium. The parser state machines are non-trivial (tracking serial/concurrent/bucket phases, per-file container waits, retry attempts), but they're pure functions over log text with a comprehensive test fixture derived from real build logs (#99854, #99975). The harness.ts change is loaded by every test file, but it's a two-line refactor that awaits the same startPromise as before through a helper that adds a console.log. The update-test-durations.mjs change alters what's committed to expected-durations.json, which feeds shard packing — the PR description argues the effect is bounded (shard estimates low by at most one container start, same order as median noise), but that's a behavioral change with a downstream consumer.
Other factors
- Stacked PR: this can't land independently; the diff bundles #35418's changes, and the PR description says it rebases to one commit once #35418 lands. A human should confirm the landing order.
- Test coverage: the new test file is thorough — covers cold/warm services, waits on non-first describes, progress dots sharing a line, pre-change lines without the suffix, bucket blocks with and without hook time in the summary, retry attempts, and clock skew flooring. The spawn test wires the real producer to both parsers so a format drift in
awaitServicefails CI. - Acknowledged flake: the PR notes
websocket-proxy.test.tsretried on 3 Linux lanes (#100069) because touching it moved it to shard front, hitting a pre-existing race with a just-started squid. The description argues it's unrelated to the one-linebeforeAllchange and didn't occur on #99975; that seems right (the swap isensure→awaitService, same await), but a maintainer may want to weigh whether that's acceptable. - No prior human or claude[bot] reviews on this PR; only coderabbit (failed to post) and robobun status.
This branch has not been deployed
1 participant
Stacked on #35418, which rewrites
parseLogin the same scripts and exports it for testing; this PR's own change is the single commit 8ae8dd7 (13 files). The base ismainwith #35418's commits merged in rather than its branch, because that branch is several hundred commits (and a WebKit pin) behind main, so basing on it would run CI and the verification build against a weeks-old tree; once #35418 lands this rebases to that one commit. Main has since deletedscripts/buildkite-slow-tests.js(#39581), which #35418 edits; the merge commit here resolves that by dropping #35418's hunk for it and the test that spawned it.Problem
scripts/ci-slowest-tests.tsandscripts/update-test-durations.mjsmeasure a serial test file as the gap between its[N/M] <path>header and the next one, and a parallel-bucket file by the figure on its summary line.describeWithContainerintest/harness.ts, or a directensure()in five files), so whichever file on a shard first touches a cold service has the whole container start inside its measured time.test/js/sql/sql-statement-cache-hash-collision.test.tsis charged 36.9 s on alpine x64 (its 3 tests finish within 90 ms of the containers coming up),test/regression/issue/24850.test.ts22.4 s,postgres-datestyle/postgres-prepared-pipeline-reorder/postgres-listen-notify15-20 s; all run in well under a second once the service is up.ci:slowesttherefore ranks them as slow tests, andupdate-test-durations.mjscommits the wait totest/expected-durations.json(postgres-datestyle: 15060 ms on the default lane today). The runner packs shards with that table, so the same file pays the same wait every build and the median keeps it. In #99854, alpine shard 0 consists of the single file24850.test.ts, placed there on the strength of its recorded duration.test/docker/prestart-map.mjs: on this PR's own CI run (#99975) 32 files waited, including24850.test.ts(22.6 s), which is in the map; a listed file still waits whenever its shard has too little work ahead of it to cover the start-up.Fix
test/docker/index.tsgainsawaitService(service, pending = ensure(service)): awaits the service and printsContainer ready via docker-compose: <service> at <host>:<ports> (waited Nms), wherewaitedis how long that call blocked.describeWithContainerand the five files that callensure()directly (sql.test.ts,valkey/test-utils.ts,s3.test.ts,autobahn.test.ts,websocket-proxy.test.ts) go through it, replacing their own ready lines, so every blocking site reports in one format. Only test processes print it; the coordinator's ownensure()calls do not (see Background for why that matters).bun test --parallelflushes each file's output as a block introduced by<path>:; the parsers attribute waits in that phase through that line and take them off the file's summary figure. On #99975 the largest wait in the whole build was in the bucket:sql-empty-column-name.test.tswaited 14-21 s formariadb_plainon all seven Linux lanes, and the bucket idled on it for ~18 s.sql-mysql.test.tsprints three lines ~4 s apart with every service already up, so "header to last line" would report 4.4 s for a 12.5 s file, while "header to first line" leaves 14.8 s onsql-statement-cache-hash-collisionon ubuntu, where mysql was up and the wait was on the second describe. Time blocked per call is ~0 in the first case and 14.75 s in the second, and summing it is right for both. Measuring from describe-definition time (whenensure()is kicked off) would have the same flaw as the last-line timestamp.<testsuite>(test time only;sql-empty-column-nameshows(0.01s)next to its 21 s wait), and runner: read each bucket file's result from its file suite in the junit report #37483 switches it to the file suite, which includes the hooks. Subtracting and flooring gives the file's own time in both cases; the worst case is zeroing a ~10 ms figure.update-test-durations.mjschanges too (this is the one behaviour change with a downstream consumer): the wait is a cost of the shard, and which file pays it depends on what else the table put on that shard, so recording it against the file feeds the placement back into the measurement. After this, container-backed files enter the table at their own cost; shard estimates can be low by one container start on shards that pay one, which is the same order as the noise the median already absorbs.ci:slowestreports the wait in amax_container_waitcolumn and lists the longest waits on stderr, tagging files missing fromtest/docker/prestart-map.mjs(the actionable kind; four of the five files above are missing, test(docker): add postgres-prepared-pipeline-reorder to prestart-map #35912 adds one). On #99975 the list is headed by those files.test/internal/ci-slowest-tests.test.ts: thecontainer start-up waitblock runs one fixture built from the #99854 and #99975 shapes (cold single service; wait on a second describe, with the line sharing a physical line with a progress dot; three warm describes with tests between them; a pre-change line without the suffix; a bucket with a block whose summary excludes the wait and one whose summary includes it, a stray line naming another file, and a file with no block; two retry attempts; a wait that rounds past the gap) through both parsers, and spawnsbun testonci-slowest-tests.fixture.tswithBUN_TEST_SERVICE_mysql_plainset so the realdescribeWithContainer->awaitServiceoutput is checked against the parsers' pattern on every lane without docker. Stashing the producer (test/docker/index.ts+test/harness.ts) fails the spawn test; stashing either parser fails its test; against the scripts: stop the slow-test parsers charging batch phases to the preceding serial test #35418 branch the file fails to import.bun bd test test/internal/ci-slowest-tests.test.ts: 22 pass.sql-empty-column-name.test.ts(20.5 s, tagged as missing from the map), and the longest untagged waits are this PR's ownautobahn.test.ts(21.4 s) andsql.test.ts(20.1 s): the runner moves the files a PR modifies to the front of the shard, ahead of the docker-last ordering, so they paid their services' cold start on this build only. The same mechanism is whywebsocket-proxy.test.tsneeded a retry on three Linux lanes here: it ran as file 3 of its shard, connected through squid within a second of the container coming up, and the first two connections gotConnection ended; the retry against the warm container passed. That race exists whenever the file runs right after squid starts and is unrelated to the one-line change in itsbeforeAll. It did not occur on the first revision's build (#99975), which did not touch the file.s3.test.tsadditionally has two pre-existing mock-endpoint tests that fail because the S3 client sends its127.0.0.1endpoint requests through the environment'sHTTP_PROXYdespiteNO_PROXYlisting it; identical without this change). Build #100069 covers them: each prints the new line on the Linux lanes that run it (minio ... (waited 7ms)on debian x64,squid ... (waited 591ms)on ubuntu, and so on) and the files pass there; the onlys3.test.tsretry in that build is the R2 lane on darwin, where the docker block does not run.bun bd test test/js/sql/postgres-datestyle.test.tsagainst the local service (printspostgres_plain at 127.0.0.1:5432 (waited 0ms)), andbun scripts/ci-slowest-tests.tson #99854 (pre-change logs: ranking identical to scripts: stop the slow-test parsers charging batch phases to the preceding serial test #35418's) and on #99975 (with the line:sql-mysql.test.ts13.87 s own / 0.02 s waited;248500.28 s own / 22.55 s waited;postgres-datestyle0.33 s / 16.12 s).Background
ESC _bk;t=<ms> BEL. The scripts take the marker on a[N/M] <path>header as a serial file's start and the next header as its end. Several markers can share a physical line (progress dots followed by a line of test output), which is why the new pattern is matched anywhere in the line.scripts/runner.node.mjsruns most files serially, and files intest/parallel-allowlist.jsonin onebun test --parallelrun (the "bucket"), after which it prints one[N/M] <path> (X.XXs)line per file from the junit report. In parallel mode bun buffers each file's output and prints it under a<path>:line when the file finishes.test/docker/coordinator.tsis spawned once per shard by the runner; it owns everydocker compose up, prestarts the services thattest/docker/prestart-map.mjslists for the shard's files (the runner also schedules those files last), and writes its own progress to the shard log asynchronously. Its lines land in whatever file's section is streaming: in #99854 a prestart'smysql_plain readyappears 36 s intobundler_compile.test.ts's section. That is why only the blocked test process may print the line the parsers subtract.test/expected-durations.jsonis regenerated byupdate-test-durations.mjsfrom recent builds and read by the runner to bin-pack files across shards (longest first) and, on the PR darwin lane, to skip files expected to exceed 10 s (container files are todo'd there anyway).Per-file spans from build #99854 (header gap; first/last ready line relative to the header)
189 of the 9371 serial spans in the build contain a ready line (33 files); 197 spans contain a coordinator
X readyline for a service the file never used.Bucket phase in build #99975, alpine aarch64 (this PR's line, before the bucket handling was added)
Same shape on all seven Linux lanes (14.4-21.1 s). The file calls
describeWithContainerbut post-dates the lastparallel-allowlist.jsonregeneration, so it currently runs in the bucket.Earlier revision of this PR
The first push only instrumented
describeWithContainer(intest/harness.ts), ignored waits printed in the bucket, and also patchedscripts/buildkite-slow-tests.js. Review found the five directensure()sites unreported, the bucket wait on #99975 invisible, and the buildkite script to be caller-less; the current revision addresses those three points.