perf(devtools): write logs on a background thread#9219
Conversation
How to use the Graphite Merge QueueAdd the label graphite: merge-when-ready to this PR to add it to the merge queue. You must have a Graphite account in order to use the merge queue. Sign up using this link. An organization admin has enabled the Graphite Merge Queue in this repository. Please do not merge from GitHub as this will restart CI on PRs being processed by the merge queue. This stack of pull requests is managed by Graphite. Learn more about stacking. |
✅ Deploy Preview for rolldown-rs ready!
To edit notification comments on pull requests, go to your Netlify project configuration. |
✅ Deploy Preview for rolldown-rs canceled.
|
cdda2ec to
2c36f7b
Compare
4322791 to
a05f380
Compare
@rolldown/browser
@rolldown/debug
@rolldown/pluginutils
rolldown
@rolldown/binding-android-arm64
@rolldown/binding-darwin-arm64
@rolldown/binding-darwin-x64
@rolldown/binding-freebsd-x64
@rolldown/binding-linux-arm-gnueabihf
@rolldown/binding-linux-arm64-gnu
@rolldown/binding-linux-arm64-musl
@rolldown/binding-linux-ppc64-gnu
@rolldown/binding-linux-s390x-gnu
@rolldown/binding-linux-x64-gnu
@rolldown/binding-linux-x64-musl
@rolldown/binding-openharmony-arm64
@rolldown/binding-wasm32-wasi
@rolldown/binding-win32-arm64-msvc
@rolldown/binding-win32-x64-msvc
commit: |
a05f380 to
3e2177e
Compare
Merging this PR will not alter performance
Comparing Footnotes
|
|
The security analysis failure does not appear to be related to this PR, because the current PR simply removes one dependency without introducing any new dependencies. I didn't dig into it because other pull requests seemed to work fine. It might be related to the cache. |
3e2177e to
3b026c7
Compare
3b026c7 to
692e373
Compare
Merge activity
|
## Summary Fixes #5896. When devtools is enabled, rolldown's wall time collapses to I/O-lock wait time. This PR moves devtools log I/O onto a dedicated background thread, removing the per-event cross-thread lock and the blocking file writes from the hot path. ### Benchmark — `vite v8.0.10` + `@vitejs/devtools`, 1,404-module antd + React app (#5896 reproduction) | build | time | |--------------------------------|--------------| | main | **27.98 s** | | this PR (04-24-perf_devtools) | **522 ms** | | **speedup** | **~54x** | ## Root cause `DevtoolsFormatter::format_event` ran on every `trace_action!`-emitted event — i.e. on every `resolve_id` / `load` / `transform` / `render_chunk` plugin hook, across every plugin. For one build session this is easily tens of thousands of events, fired from every tokio worker in parallel. Before this PR, the formatter did all of this synchronously on the caller: 1. `OPENED_FILE_HANDLES.get_mut(&log_filename)` (a `DashMap<Arc<str>, File>`), which takes a **per-shard `parking_lot::RwLock` write guard**. 2. Held that guard across two full JSON-serialization passes (one for StringRef dedupe, one for the event line), the `WriteFile` syscall(s), and `file.flush()`. 3. Every session funnels all events into the same filename (`node_modules/.rolldown/<session>/logs.json`) → same DashMap key → same shard → **one lock serializing every tokio worker**. The ETW profile made this unambiguous: with devtools on, **83% of all samples landed at `ntdll!NtWaitForAlertByThreadId`**, **99% of total thread time in `format_event` was in System Libraries** (parking in `parking_lot` via `WaitOnAddress`), and only **~1.2% of samples were actually executing Rust**. The call path was always \`\`\` NtWaitForAlertByThreadId -> WaitOnAddress -> parking_lot::park -> parking_lot::RawRwLock::lock_exclusive_slow -> dashmap::DashMap::_yield_write_shared -> dashmap::DashMap::get_mut -> rolldown_devtools::devtools_formatter::impl\$1::format_event \`\`\` So the slowdown wasn't \"more work\" — the actual Rust CPU work only grew ~5x. It was **cross-thread lock contention** serializing all worker threads onto one I/O-holding RwLock. ## Fix Move all log I/O to a single dedicated `rolldown-devtools-writer` thread. Producers (the tokio workers running plugin hooks) do a fire-and-forget `Sender::send` over `std::sync::mpsc`: - New `rolldown_devtools::writer` module owns the channel, the `BufWriter<File>` per log file, the per-session file tracking, and the per-session StringRef-dedupe hash set. - `DevtoolsFormatter::format_event` now only does the JSON shaping that needs event-local context (placeholder resolution via span extensions, filename selection), then sends `LogCommand::Write { session_id, filename, action_value }` and returns. **No cross-thread lock is taken, no syscall is issued, on the hot path.** - Removed `OPENED_FILE_HANDLES`, `OPENED_FILES_BY_SESSION`, `EXIST_HASH_BY_SESSION` (and the `dashmap` dep) — all that state now lives on the writer thread where no synchronization is needed. - Directory creation is memoised per-session on the writer (`dir_ensured` set), instead of a `create_dir_all` syscall per event. - `BufWriter` batches small `serde_json` writes into ~8 KB chunks, cutting `WriteFile` syscall count dramatically compared to the previous `serde_json::Serializer::new(&mut file)` -> raw `File` path. ### Read-after-close contract Because log I/O is now asynchronous and buffered, consumers reading `meta.json` / `logs.json` immediately after `generate()` / `write()` could see truncated content. To preserve the expectation that **the log files are readable and complete once `await bundle.close()` resolves**, `ClassicBundler::close()` now: 1. Snapshots whether devtools is active (`self.debug_tracer.is_some()`). 2. Calls `rolldown_devtools::flush_session(session_id)`, which sends `LogCommand::CloseSession { session_id, ack: Some(tx) }` and returns the corresponding `Receiver<()>`. 3. `spawn_blocking`s `rx.recv_timeout(30s)` so a stalled fs (e.g. NFS disconnect) can't wedge `close()` indefinitely, and surfaces timeout / disconnect as errors rather than silently truncating logs. `DebugTracer::Drop` still sends a best-effort no-ack `CloseSession` for the abnormal-exit path; the authoritative flush path is `ClassicBundler::close()`. Documented in `meta/design/devtools.md`. ## Why this is faster - **No lock contention on the hot path.** Previously N tokio workers serialized on one `parking_lot::RwLock` write guard held across I/O; now they only contend on `std::sync::mpsc`'s sender, which is lock-free-ish and never held across I/O. - **Producer / writer pipelining.** On main, log I/O was on the critical path of every worker task. Now workers return to doing compile work the moment they hand off the event; the writer thread drains the queue in parallel with them. Total wall time becomes `max(compute, log_drain)` instead of `sum`. - **Fewer syscalls.** `BufWriter` + per-session cached `create_dir_all` eliminate the per-event `mkdir` syscall and collapse each event's many `write()` calls into one. This PR is strictly about unblocking the hot path. Other independent wins (lazy `content: Some(code.clone())` in `trace_action!` payloads, single-pass StringRef dedupe, skipping the JSON-string round-trip through `DevtoolsActionFieldExtractor`) are deliberately left for follow-ups — they reduce CPU work, but CPU was never the bottleneck. ## Test plan - [ ] `cargo test --workspace` green - [ ] Manual: run an antd build with `devtools: {}`, confirm `node_modules/.rolldown/<sid>/{meta,logs}.json` are well-formed JSON-lines and contain the expected action events - [ ] Manual: confirm log files are complete after `await bundle.close()` (read file in a Node consumer immediately after close, assert last line parses) - [ ] Re-record samply profile on the antd repro — verify `format_event` is no longer a hotspot and Rust-leaf sample share recovers
692e373 to
2b23515
Compare
## [1.0.0] - 2026-05-07 ### 🐛 Bug Fixes - dev/lazy: lazily compiled modules should be watched (#9301) by @h-a-n-a - implement dynamic dominator merge logic (#9270) by @TheAlexLichter - dev: apply __toCommonJS interop when CJS requires ESM in HMR finalizer (#9261) by @h-a-n-a ### 🚜 Refactor - ecma_ast: tighten allocator access to enforce Sync invariant (#9278) by @IWANABETHATGUY - scan_stage: remove stmt_infos field from EcmaView (#9276) by @IWANABETHATGUY - link_stage: detach stmt_infos from EcmaView (#9274) by @IWANABETHATGUY - link_stage: detach depended_runtime_helper from EcmaView to remove unsafe (#9265) by @IWANABETHATGUY - link_stage: remove unsafe in determine_module_exports_kind (#9253) by @IWANABETHATGUY ### 📚 Documentation - getting-started: remove RC warning for 1.0.0 release (#9310) by @shulaoda - getting-started: update version references for 1.0.0 release (#9309) by @shulaoda - add Vite+ tab to getting-started snippets (#9285) by @shulaoda - lazy-barrel: clarify own-exports behavior for import-then-export records (#9298) by @shulaoda - restructure top navigation around Learn vs Reference (#9284) by @shulaoda - builtin-plugins: add bundle analyzer plugin docs (#9292) by @shulaoda - design doc for reference_needed_symbols (#9264) by @IWANABETHATGUY ### ⚡ Performance - devtools: write logs on a background thread (#9219) by @IWANABETHATGUY ### ⚙️ Miscellaneous Tasks - mark esbuild/ts/parameter_props_use_define_for_class_fields_true as passed (#9308) by @sapphi-red - deps: upgrade oxc to 0.129.0 (#9297) by @shulaoda - deps: update rollup submodule for tests to v4.60.3 (#9294) by @sapphi-red - deps: update test262 submodule for tests (#9295) by @sapphi-red - ai: add rolldown REPL decode skill (#9245) by @Dunqing
## [1.0.0] - 2026-05-07 ### 🐛 Bug Fixes - dev/lazy: lazily compiled modules should be watched (rolldown#9301) by @h-a-n-a - implement dynamic dominator merge logic (rolldown#9270) by @TheAlexLichter - dev: apply __toCommonJS interop when CJS requires ESM in HMR finalizer (rolldown#9261) by @h-a-n-a ### 🚜 Refactor - ecma_ast: tighten allocator access to enforce Sync invariant (rolldown#9278) by @IWANABETHATGUY - scan_stage: remove stmt_infos field from EcmaView (rolldown#9276) by @IWANABETHATGUY - link_stage: detach stmt_infos from EcmaView (rolldown#9274) by @IWANABETHATGUY - link_stage: detach depended_runtime_helper from EcmaView to remove unsafe (rolldown#9265) by @IWANABETHATGUY - link_stage: remove unsafe in determine_module_exports_kind (rolldown#9253) by @IWANABETHATGUY ### 📚 Documentation - getting-started: remove RC warning for 1.0.0 release (rolldown#9310) by @shulaoda - getting-started: update version references for 1.0.0 release (rolldown#9309) by @shulaoda - add Vite+ tab to getting-started snippets (rolldown#9285) by @shulaoda - lazy-barrel: clarify own-exports behavior for import-then-export records (rolldown#9298) by @shulaoda - restructure top navigation around Learn vs Reference (rolldown#9284) by @shulaoda - builtin-plugins: add bundle analyzer plugin docs (rolldown#9292) by @shulaoda - design doc for reference_needed_symbols (rolldown#9264) by @IWANABETHATGUY ### ⚡ Performance - devtools: write logs on a background thread (rolldown#9219) by @IWANABETHATGUY ### ⚙️ Miscellaneous Tasks - mark esbuild/ts/parameter_props_use_define_for_class_fields_true as passed (rolldown#9308) by @sapphi-red - deps: upgrade oxc to 0.129.0 (rolldown#9297) by @shulaoda - deps: update rollup submodule for tests to v4.60.3 (rolldown#9294) by @sapphi-red - deps: update test262 submodule for tests (rolldown#9295) by @sapphi-red - ai: add rolldown REPL decode skill (rolldown#9245) by @Dunqing Co-authored-by: shulaoda <[email protected]>

Summary
Fixes #5896. When devtools is enabled, rolldown's wall time collapses to I/O-lock wait time. This PR moves devtools log I/O onto a dedicated background thread, removing the per-event cross-thread lock and the blocking file writes from the hot path.
Benchmark —
vite v8.0.10+@vitejs/devtools, 1,404-module antd + React app (#5896 reproduction)Root cause
DevtoolsFormatter::format_eventran on everytrace_action!-emitted event — i.e. on everyresolve_id/load/transform/render_chunkplugin hook, across every plugin. For one build session this is easily tens of thousands of events, fired from every tokio worker in parallel.Before this PR, the formatter did all of this synchronously on the caller:
OPENED_FILE_HANDLES.get_mut(&log_filename)(aDashMap<Arc<str>, File>), which takes a per-shardparking_lot::RwLockwrite guard.WriteFilesyscall(s), andfile.flush().node_modules/.rolldown/<session>/logs.json) → same DashMap key → same shard → one lock serializing every tokio worker.The ETW profile made this unambiguous: with devtools on, 83% of all samples landed at
ntdll!NtWaitForAlertByThreadId, 99% of total thread time informat_eventwas in System Libraries (parking inparking_lotviaWaitOnAddress), and only ~1.2% of samples were actually executing Rust. The call path was always```
NtWaitForAlertByThreadId -> WaitOnAddress -> parking_lot::park ->
parking_lot::RawRwLock::lock_exclusive_slow ->
dashmap::DashMap::_yield_write_shared ->
dashmap::DashMap::get_mut ->
rolldown_devtools::devtools_formatter::impl$1::format_event
```
So the slowdown wasn't "more work" — the actual Rust CPU work only grew ~5x. It was cross-thread lock contention serializing all worker threads onto one I/O-holding RwLock.
Fix
Move all log I/O to a single dedicated
rolldown-devtools-writerthread. Producers (the tokio workers running plugin hooks) do a fire-and-forgetSender::sendoverstd::sync::mpsc:rolldown_devtools::writermodule owns the channel, theBufWriter<File>per log file, the per-session file tracking, and the per-session StringRef-dedupe hash set.DevtoolsFormatter::format_eventnow only does the JSON shaping that needs event-local context (placeholder resolution via span extensions, filename selection), then sendsLogCommand::Write { session_id, filename, action_value }and returns. No cross-thread lock is taken, no syscall is issued, on the hot path.OPENED_FILE_HANDLES,OPENED_FILES_BY_SESSION,EXIST_HASH_BY_SESSION(and thedashmapdep) — all that state now lives on the writer thread where no synchronization is needed.dir_ensuredset), instead of acreate_dir_allsyscall per event.BufWriterbatches smallserde_jsonwrites into ~8 KB chunks, cuttingWriteFilesyscall count dramatically compared to the previousserde_json::Serializer::new(&mut file)-> rawFilepath.Read-after-close contract
Because log I/O is now asynchronous and buffered, consumers reading
meta.json/logs.jsonimmediately aftergenerate()/write()could see truncated content. To preserve the expectation that the log files are readable and complete onceawait bundle.close()resolves,ClassicBundler::close()now:self.debug_tracer.is_some()).rolldown_devtools::flush_session(session_id), which sendsLogCommand::CloseSession { session_id, ack: Some(tx) }and returns the correspondingReceiver<()>.spawn_blockingsrx.recv_timeout(30s)so a stalled fs (e.g. NFS disconnect) can't wedgeclose()indefinitely, and surfaces timeout / disconnect as errors rather than silently truncating logs.DebugTracer::Dropstill sends a best-effort no-ackCloseSessionfor the abnormal-exit path; the authoritative flush path isClassicBundler::close(). Documented inmeta/design/devtools.md.Why this is faster
parking_lot::RwLockwrite guard held across I/O; now they only contend onstd::sync::mpsc's sender, which is lock-free-ish and never held across I/O.max(compute, log_drain)instead ofsum.BufWriter+ per-session cachedcreate_dir_alleliminate the per-eventmkdirsyscall and collapse each event's manywrite()calls into one.This PR is strictly about unblocking the hot path. Other independent wins (lazy
content: Some(code.clone())intrace_action!payloads, single-pass StringRef dedupe, skipping the JSON-string round-trip throughDevtoolsActionFieldExtractor) are deliberately left for follow-ups — they reduce CPU work, but CPU was never the bottleneck.Test plan
cargo test --workspacegreendevtools: {}, confirmnode_modules/.rolldown/<sid>/{meta,logs}.jsonare well-formed JSON-lines and contain the expected action eventsawait bundle.close()(read file in a Node consumer immediately after close, assert last line parses)format_eventis no longer a hotspot and Rust-leaf sample share recovers