event loop: run completions left on the macro loop after the macro returned

Closed
RO
3mo ago
+130-61

Problem

  • Since #37075, bun index.ts where index.ts calls a macro that starts async work without awaiting it (an un-awaited fs.promises.stat(), fetch() or crypto.subtle.digest() inside the macro; the same at the macro module's top level when the work outlasts loading that module) prints its output and then never exits. 1.3.14 exits 0.
  • Off-thread work now captures its destination loop when it is created: Job::schedule takes vm.ticket() (src/jsc/job.rs:331), which records current_loop_kind() (src/jsc/VmHandle.rs:519, src/jsc/VirtualMachine.rs:903). While a macro runs that is LoopKind::Macro, so the completion is posted to macro_event_loop.concurrent_tasks (loop_of + push, src/jsc/VmHandle.rs:159-179).
  • The macro loop only ticks inside wait_for_promise while a macro is being waited on. Once the macro has returned nothing pops that queue, and the job's keep-alive (taken on the uSockets loop both embedded loops share, job.rs:316, released only when the completion runs) keeps is_event_loop_alive() true forever.
  • The macro loop has a second per-loop channel with the same problem: a Macro-kind Ticket::unref_keep_alive() (VmHandle.rs:245, used by WebCrypto's work queue, src/jsc/CppTask.rs:75, for inputs hashed off thread) adds its -1 to macro_event_loop.concurrent_ref, which only a tick of that loop folds into the platform loop. The WebCrypto result itself is posted to the regular loop and runs; the keep-alive is what stays stuck. This channel exists since #38299 made ConcurrentCppTask carry a ticket instead of always releasing on the regular loop.
  • Before #37075 the producers looked the loop up at completion time and landed on the regular loop, which is why this used to work.

Fix

  • EventLoop::tick_concurrent_with_count on the regular loop also services the macro loop: it folds that loop's concurrent_ref delta (apply_concurrent_ref_delta, the same function each loop runs on itself) and pops its concurrent queue. Gated by finished_macro_loop() (src/jsc/event_loop.rs:551): the VM has run a macro (has_enabled_macro_mode), no macro is running right now (!macro_mode), and the loop doing the drain is the regular one (so the macro loop itself and spawnSync's isolated loop never adopt it).
  • The exit decision sees the same state: has_pending_tasks() (poll must not block) and is_event_loop_alive_excluding_immediates() go through has_concurrent_tasks(), and has_pending_refs() also looks at the macro loop, so work sitting on the macro loop counts the same as work on the regular loop.
  • Correct because at any moment only one of the two loops ticks: while a macro runs, vm.event_loop points at the macro loop and it services itself as before (awaited macros are unchanged, and the regular loop's queue still waits until the macro returns); once it returns, the regular loop owns whatever is left or arrives later. A post or unref already wakes the shared platform loop, so a late one is picked up on the next tick. Draining only in disable_macro_mode() would not be enough: in the repro the completion is posted after that runs. Picking the loop at post time instead would put a read of the JS thread's macro state back on the posting thread, which is the race #37075 removed.
  • For programs that never run a macro the drain is unchanged apart from one bool check (has_enabled_macro_mode is false). The batch transfer into tasks is factored into take_concurrent_batch (built on ConcurrentTask::into_task), which the teardown release path (release_queued_tasks) now shares instead of carrying its own copy.
  • Rebased onto main after #38299 (tickets + the waiting teardown) merged; the diff applies unchanged there, since it only touches the drain on the consuming side. Re-verified on main at 7ba276f: the three in-macro cases below still hang without the fix and pass with it.
  • Verified with test/bundler/transpiler/macro-test.test.ts, four new cases that assert the child prints both the macro's value and the un-awaited continuation's output and exits 0. The three cases that start the work inside the macro call (fs.promises, fetch(), a 4 KiB crypto.subtle.digest()) time out without the fix (the child never exits) and pass with it; the digest case also times out with only the first commit of this PR. The top-level fs.stat case passes either way on current main, because the stat usually completes while the macro loop is still being ticked to load the macro module; it covers the continuation running from the macro loop. Top-level work that outlasts the module load (a fetch against a server that answers after 300 ms, checked by hand) hangs without the fix and exits with it. The rest of that file, transpiler.test.js, the macro cases in bundler_edgecase / bun-build-api, web-crypto.test.ts, spawn.test.ts and the worker teardown tests pass with the debug build; the file also passes with a release build.

Background

  • A VM embeds two EventLoops, regular_event_loop and macro_event_loop, plus vm.event_loop, a pointer to whichever is current. MacroModeGuard points it at the macro loop for the duration of a macro call (and of loading the macro module) so that the user program's queued work does not run in the middle of transpiling; a macro that returns a promise is settled by ticking that loop. Both loops sit on the same uSockets/libuv platform loop, whose active count is what keep-alives adjust and what is_event_loop_alive() reads.
  • Each EventLoop has two things other threads write to: concurrent_tasks, the MPSC queue of completions (each tick moves a batch of it into the loop's own tasks FIFO and runs them), and concurrent_ref, a pending keep-alive delta that apply_concurrent_ref_delta folds into the platform loop's active count at the top of each tick. A Ticket (VmHandle.rs) is what off-thread work holds to reach either; its LoopKind, fixed when the work is created, says which loop's pair it writes to.
  • In bun run, macros in the entry file (and in every file when transpiling happens on the main thread, e.g. with plugins) execute in the main VM, which is why this hangs the process. Macros in files transpiled on the thread pool and in bun build run in per-thread VMs whose regular loop never ticks, so there the same stranded work is only a leak, which is unchanged here.
  • A sync macro calling setImmediate() also hangs, on 1.3.14 as well (immediates are per-loop too); that is pre-existing and not touched by this change.

[review] gate passed · iteration 2 · 4 files touched

fails on main (without fix) 
ASAN without fix: 3 FAILED
$ BUN_DEBUG_QUIET_LOGS=1 bun scripts/build.ts --profile=debug --quiet test "--reporter=junit" "--reporter-outfile=/tmp/mechgate.xml" test/bundler/transpiler/macro-test.test.ts
bun test v1.4.0 (af84237cd)

test/bundler/transpiler/macro-test.test.ts:
[macro] call escapeHTML
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call escape
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] c
... (truncated)

release without fix: 3 FAILED
bun test v1.4.0-canary.1 (b7a043103)

test/bundler/transpiler/macro-test.test.ts:
(pass) bun builtins can be used in macros [0.04ms]
(pass) latin1 string [0.01ms]
(pass) ascii string
(pass) type coercion [0.09ms]
(pass) escaping [0.15ms]
(pass) utf16 string
(pass) import aliases [0.02ms]
(pass) default import [0.01ms]
(pass) namespace import [0.02ms]
(pass) ireturnapromise [0.07ms]
(pass) object argument with a sparse numeric key [9.95ms]
(pass) object destructuring of a macro result keeps every bound property regardless of key order or repeated keys [8.28ms]
(pass) work a macro starts without awaiting it > a crypto.subtle.digest() inside the macro still lets the process exit [8.20ms]
(fail) work a macro starts without awaiting it > an fs.promises call inside the macro still lets the process exit [5000.09ms]
  ^ this test timed out after 5000ms.
(fail) work a macro starts without awaiting it > an fs.promises call at the macro module's top level still lets the process exit [5000.07ms]
  ^ this test timed out after 5000ms.
(fail) work a macro starts without awaiting it > a fetch() inside the macro still lets the process exit [5000.06ms]
  ^ this test timed out after 5
... (truncated)
passes on PR (with fix) 
ASAN with fix: all passed
$ BUN_DEBUG_QUIET_LOGS=1 bun scripts/build.ts --profile=debug --quiet test "--reporter=junit" "--reporter-outfile=/tmp/mechgate.xml" test/bundler/transpiler/macro-test.test.ts
bun test v1.4.0 (af84237cd)

test/bundler/transpiler/macro-test.test.ts:
[macro] call escapeHTML
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call identity
[macro] call escape
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] call addStrings
[macro] c
... (truncated)

release with fix: all passed
$ bun scripts/build.ts --profile=release
[configured] bun-profile → bun (stripped) in 667ms (unchanged)
ninja: Entering directory `/workspace/bun/build/release'
[1/663] cc obj/vendor/tinycc/x86_64-gen.c.o
[2/663] cc obj/vendor/tinycc/tccelf.c.o
[3/663] cc obj/vendor/tinycc/x86_64-link.c.o
[4/663] cc obj/vendor/tinycc/tccrun.c.o
[5/663] cc obj/vendor/tinycc/tccasm.c.o
[6/663] cc obj/vendor/tinycc/i386-asm.c.o
[7/663] fetch boringssl
[boringssl] up to date
[8/241] fetch hdrhistogram
[hdrhistogram] up to date
[9/238] fetch mimalloc
[mimalloc] up to date
[10/238] gen ZigGeneratedClasses.lut.h
Generating /workspace/bun/build/release/codegen/ZigGeneratedClasses.lut.h from /workspace/bun/build/release/codegen/ZigGeneratedClasses.lut.txt
[11/238] fetch highway
[highway] up to date
[12/229] gen bake.{client,server,error}.js
-> bake.client.js, bake.server.js, bake.error.js
[13/229] cc obj/codegen/InternalModuleRegistryConstants.S.o
[14/229] fetch lolhtml
[lolhtml] up to date
[15/229] fetch WebKit (prebuilt)
[WebKit] up to date
[16/229] cc obj/vendor/mimalloc/src/static.c.o
[17/229] fetch lsquic
[lsquic] up to date
[18/160] cc obj/packages/bun-usockets/src/udp.c.o
[19/160] c
... (truncated)
diff hotspot 
src/jsc/VirtualMachine.rs                  |   2 +-
 src/jsc/VmHandle.rs                        |   2 +
 src/jsc/event_loop.rs                      | 108 +++++++++++++----------------
 test/bundler/transpiler/macro-test.test.ts |  79 +++++++++++++++++++++
 4 files changed, 130 insertions(+), 61 deletions(-)

gate history · 2 passed · 1 rejected · iteration 2

evidence per changed file 
file                                        reads  edits  tests
src/jsc/VirtualMachine.rs                       5      1      0
src/jsc/VmHandle.rs                             6      7      0
src/jsc/event_loop.rs                          17     15      0
test/bundler/transpiler/macro-test.test.ts      3      5      0