test(serve): speed up serve.test.ts (~34s to ~16s release) and tighten its assertions
RO
3mo ago+140+140+012345678901234567890123456789-93-93-01234567890123456789
Problem
test/js/bun/http/serve.test.tstakes 25-33s on every CI lane (33s on debian x64 ASAN in build 97275, 25s on the aarch64 release lane), so most of the time is waiting, not running.- Release profile before (34.4s locally):
should reset timeout after writes15.0s,allow custom timeout per request10.0s,should allow use of custom timeout6.5-8s. They are in oneit.concurrentgroup, so they cost ~15s of wall clock on every lane. Each one slept for a fixed 10-15s on top of uSockets' 4s timeout sweep. - Next in line: the two
1000 uploads & downloads ... do not leak ReadableStreamcases (2.0s + 2.2s release, 23s + 25s in this container's debug build). Each of their requests asked for a full collection twice:Bun.gc(false)and, under theBUN_GARBAGE_COLLECTOR_LEVEL=1that the CI runner sets, the per-requestexpect()(every matcher schedules a collection in that mode). That was ~40% of their time; the loop also ran 1024 requests, not the 1000 it asserts on. - Then the
request body backpressuredescribe (6 cases, ~0.4s each, all of it waiting for an upload to plateau), the two proxying RSS cases (1.1s + 0.7s, each a subprocess with a fixed 500ms stall) and four subprocess-only tests right after the timeout group, all running one after another. - Weak spots in the same tests:
request body and signal life cycleended inexpect().pass(), the timeout tests had unawaited.resolves/.rejectsassertions, and the leak test stopped at the first wrong digest.
Fix
- Timeout tests: uSockets checks timeouts once every 4s and arms them in whole sweeps (
idleTimeout1..4 fires at the next sweep, 5..8 at the one after), so each test now leaves one request unanswered and waits for the server to close it instead of sleeping:should allow use of custom timeout(idleTimeout: 1): the stalled streaming response must be closed (client seesECONNRESET, server seesreq.signalabort);/okis then served right after that sweep, so it has a whole sweep interval to complete and also shows the server still works after timing a request out.should reset timeout after writes(idleTimeout: 5, two sweeps, because a one-sweep timeout fires at the next sweep whether or not a write re-armed it): the stream writes every 100ms; an unanswered canary is opened only after the stream has started, so its timeout is armed no earlier than the stream's. Once the canary is closed, the stream has outlived the sweep that would have closed it without the resets. The test then stops the stream itself and checks status, that the stream request was never aborted, and that the body holds exactly the chunks that were written.allow custom timeout per request(idleTimeout: 1,server.timeout(req, 60)): the canary is opened after the long request has raised its own timeout; once the canary is closed the long request must still be unaborted, and is only then released and checked for status and body.- In both canary tests the release is driven from the test body after the client has seen the canary fail. Releasing from the canary's server-side abort event does not work: that event fires inside the sweep, the handler's response is written before the sweep reaches the other socket, and the write re-arms it (verified: that variant passed with
server.timeout()removed). - Each rewritten test was checked against the regression it guards by removing the behaviour under test (stream writes removed;
server.timeout()call removed): both variants fail at thetoBe(false)abort assertions, at the same sweep that closes the canary. Output in the details below. - The group now takes one or two sweeps: 4-8s depending on the sweep phase (5.9s in the release run below, 0.3s / 1.1s / 4.5s for the three tests in the debug run). The 4s sweep period is the floor for this approach; #38470 does the same for fetch.test.ts. The original per-test timeouts (15s / 20s / 20s) are kept, which also leaves room if #33610 adds a sweep to every timeout.
- Leak test: collects every fourth completed request (so collections still happen while the rest of the batch is in flight), runs exactly
countrequests, and asserts{ completed, wrongDigests }once at the end. The post-GCReadableStreamcount assertion is unchanged. This is where the file'sexpect()count drops (3802 to 1759). - Concurrency: the four subprocess-only tests after the timeout group are
it.concurrentand so join that group (they finish inside its sweep wait);request body backpressureisdescribe.concurrent(each case has its own server and socket, and a plateau check can only end early if the upload stops, which is the property under test); the RSS pair isit.concurrent.each(separate subprocesses, RSS is per process), with its explicit timeout raised from 10s to 15s since the two fixtures now share the CPU. The other plateau tests move 32-128MB each on the test thread, so they were left sequential: concurrently they were not faster in the debug build, only closer to the 5s local default timeout. - Assertions: life cycle test checks all 640 responses are 200 (bodies are still left unread, which is what the test exercises); timeout tests check status and body via one
toEqual, the unanswered request'scode: "ECONNRESET"(also for the stalled stream, matching what #35988 proposes for that line) and that the request under test was not aborted; leak test reports the request count and every wrong digest. - Verified (this container; debug builds here are several times slower than CI):
bun bd test test/js/bun/http/serve.test.ts: 141.3s before, 111.6s after. With the CI runner's env (BUN_GARBAGE_COLLECTOR_LEVEL=1,BUN_JSC_randomIntegrityAuditRate=1.0): 155.1s before, 121.6s after.USE_SYSTEM_BUN=1 bun test test/js/bun/http/serve.test.ts(release): 34.4s before, 16.2s and 16.3s after.- The tests touched here plus the rest of their concurrent group, 6 runs in a loop on the debug build: green every time (timeout tests landing anywhere between 0.3s and 2.5s / 4.5s and 6.9s depending on sweep phase).
- The failing set is identical before and after and is this container's environment:
server.requestIP > v6(no IPv6),root range port(#7187)(running as root),#6583(localhostresolves to the other family than the server bound),only serves /bun:info to loopback clients(egress proxy). The release binary additionally failsreload() that drops the node:http handler, which needs #38755 and passes on the debug build.
it.concurrent(name, fn)with a title longer than prettier's line width re-indents thedoes not dispatch a pipelined request ...test;git diff -wshows the real changes (124 insertions, 77 deletions).- Of the 54 open PRs that touch this file, 52 still apply on top of this branch exactly as they do on main (checked by applying each PR's serve.test.ts patch to both versions). The two that do not, #33610 and #35988, both edit the assertions of the old
should allow use of custom timeouttest that this PR rewrites; thecode-based assertion here already covers what #35988 changes that line to.
Background
Bun.serve'sidleTimeoutandserver.timeout(req, s)are uSockets socket timeouts. uSockets only walks its sockets everyLIBUS_TIMEOUT_GRANULARITY(4) seconds andus_socket_timeout(s, seconds)storesnow_tick + ceil(seconds / 4), so a 1s timeout fires at the next sweep (0-4s later, exactly 4s when this test's sockets are the ones that start the sweep timer) and a 5s one at the second sweep. Every write to the response re-arms the socket with the same value, which is whatshould reset timeout after writestests and why it needs a two-sweep value. When a timeout fires uSockets force-closes the socket; a pending request seesreq.signalabort and Bun'sfetch()rejects withcode: "ECONNRESET"(theConnectionClosedmapping inFetchTasklet.rs), whether or not the head had been sent.- A request opened after another one has its timeout armed at the same tick or later, so "request B was closed by its timeout" implies "a sweep ran that would also have closed request A unless A's timeout had been reset or raised". That is the only ordering the rewritten tests rely on; they do not depend on the length of a tick.
- Bun's
fetch()retries an idempotent request once if a pooled keep-alive connection closes under it, but never on a fresh connection (allow_retryis only set when a pooled socket is reused,HTTPContext.rs). Each server here is new and its first connection is still busy when the canary is sent, so the canary always uses a fresh connection and its close is reported, not retried. it.concurrenttests run together with theit.concurrent/describe.concurrenttests declared directly before and after them; a plainitin between is a barrier, and so is the end of adescribeblock (checked with a small probe file: tests declared after a describe block closes start a new batch,.eachdoes not). That is why the four subprocess tests, which follow the timeout group at top level, join it, while the backpressure describe and the RSS pair each form their own batch. The CI runner passes--timeout=90000(x3 on ASAN), and an explicit per-test timeout overrides that, which is why the only explicit timeout on a newly concurrent test was raised rather than added anywhere else.
Simulated regressions, debug build
Stream writes removed from should reset timeout after writes, and server.timeout(req, 60) removed from allow custom timeout per request (the real tests were run in the same file for comparison):
error: expect(received).toBe(expected)
Expected: false
Received: true
(fail) MUTATION per-request (must fail) [4134.84ms]
(pass) allow custom timeout per request [4224.84ms]
(pass) should allow use of custom timeout [4401.60ms]
error: expect(received).toBe(expected)
Expected: false
Received: true
(fail) MUTATION reset (must fail) [8103.94ms]
(pass) should reset timeout after writes [8189.55ms]
The earlier variant that released the long request from the canary's server-side abort event passed without server.timeout(), which is why the release now comes from the test body after the client has observed the canary's failure.
Release profile after (16.3s total)
5873ms should reset timeout after writes (group wall clock; the other two landed at ~1.9s in the same run)
1937ms 1000 uploads ... > direct
1835ms 1000 uploads ... > default
1108ms bounds memory ... chunked (runs together with content-length, 728ms)
1063ms request body backpressure > Bun.write (the describe's 6 cases run together)
349ms type: direct stream awaiting flush(true) ...
340ms resumes a backpressured Response(ReadableStream) ...
338ms applies backpressure to a Response(ReadableStream) body ...
What is left is the 4-8s sweep floor of the timeout group, ~3.8s of the two leak cases (768KB uploaded and hashed per request; their payload size is what makes the request body arrive in more than one chunk, so it was left alone), and ~4s spread across the remaining ~280 tests.