Skip to content

perf(devtools): write logs on a background thread#9219

Merged
graphite-app[bot] merged 1 commit into
mainfrom
04-24-perf_devtools
May 5, 2026
Merged

perf(devtools): write logs on a background thread#9219
graphite-app[bot] merged 1 commit into
mainfrom
04-24-perf_devtools

Conversation

@IWANABETHATGUY

@IWANABETHATGUY IWANABETHATGUY commented Apr 24, 2026

Copy link
Copy Markdown
Member

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_blockings 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

Copy link
Copy Markdown
Member Author

How to use the Graphite Merge Queue

Add 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.

@netlify

netlify Bot commented Apr 24, 2026

Copy link
Copy Markdown

Deploy Preview for rolldown-rs ready!

Name Link
🔨 Latest commit 9d0c2f7
🔍 Latest deploy log https://app.netlify.com/projects/rolldown-rs/deploys/69eaf8b8c8afde000882eb98
😎 Deploy Preview https://deploy-preview-9219--rolldown-rs.netlify.app
📱 Preview on mobile
Toggle QR Code...

QR Code

Use your smartphone camera to open QR code link.

To edit notification comments on pull requests, go to your Netlify project configuration.

@netlify

netlify Bot commented Apr 24, 2026

Copy link
Copy Markdown

Deploy Preview for rolldown-rs canceled.

Name Link
🔨 Latest commit 2b23515
🔍 Latest deploy log https://app.netlify.com/projects/rolldown-rs/deploys/69f98da878635b00083baf7c

@IWANABETHATGUY IWANABETHATGUY changed the title perf: devtools perf(devtools): write logs on a background thread (~39x faster when enabled) Apr 24, 2026
@IWANABETHATGUY
IWANABETHATGUY force-pushed the 04-24-perf_devtools branch 2 times, most recently from 4322791 to a05f380 Compare April 24, 2026 05:56
@pkg-pr-new

pkg-pr-new Bot commented Apr 24, 2026

Copy link
Copy Markdown

Open in StackBlitz

@rolldown/browser

npm i https://pkg.pr.new/@rolldown/browser@9219

@rolldown/debug

npm i https://pkg.pr.new/@rolldown/debug@9219

@rolldown/pluginutils

npm i https://pkg.pr.new/@rolldown/pluginutils@9219

rolldown

npm i https://pkg.pr.new/rolldown@9219

@rolldown/binding-android-arm64

npm i https://pkg.pr.new/@rolldown/binding-android-arm64@9219

@rolldown/binding-darwin-arm64

npm i https://pkg.pr.new/@rolldown/binding-darwin-arm64@9219

@rolldown/binding-darwin-x64

npm i https://pkg.pr.new/@rolldown/binding-darwin-x64@9219

@rolldown/binding-freebsd-x64

npm i https://pkg.pr.new/@rolldown/binding-freebsd-x64@9219

@rolldown/binding-linux-arm-gnueabihf

npm i https://pkg.pr.new/@rolldown/binding-linux-arm-gnueabihf@9219

@rolldown/binding-linux-arm64-gnu

npm i https://pkg.pr.new/@rolldown/binding-linux-arm64-gnu@9219

@rolldown/binding-linux-arm64-musl

npm i https://pkg.pr.new/@rolldown/binding-linux-arm64-musl@9219

@rolldown/binding-linux-ppc64-gnu

npm i https://pkg.pr.new/@rolldown/binding-linux-ppc64-gnu@9219

@rolldown/binding-linux-s390x-gnu

npm i https://pkg.pr.new/@rolldown/binding-linux-s390x-gnu@9219

@rolldown/binding-linux-x64-gnu

npm i https://pkg.pr.new/@rolldown/binding-linux-x64-gnu@9219

@rolldown/binding-linux-x64-musl

npm i https://pkg.pr.new/@rolldown/binding-linux-x64-musl@9219

@rolldown/binding-openharmony-arm64

npm i https://pkg.pr.new/@rolldown/binding-openharmony-arm64@9219

@rolldown/binding-wasm32-wasi

npm i https://pkg.pr.new/@rolldown/binding-wasm32-wasi@9219

@rolldown/binding-win32-arm64-msvc

npm i https://pkg.pr.new/@rolldown/binding-win32-arm64-msvc@9219

@rolldown/binding-win32-x64-msvc

npm i https://pkg.pr.new/@rolldown/binding-win32-x64-msvc@9219

commit: a05f380

@IWANABETHATGUY IWANABETHATGUY changed the title perf(devtools): write logs on a background thread (~39x faster when enabled) perf(devtools): write logs on a background thread Apr 24, 2026
@IWANABETHATGUY
IWANABETHATGUY marked this pull request as ready for review April 25, 2026 04:00
@IWANABETHATGUY
IWANABETHATGUY requested a review from hyfdev April 25, 2026 04:01
@codspeed-hq

codspeed-hq Bot commented Apr 25, 2026

Copy link
Copy Markdown

Merging this PR will not alter performance

✅ 4 untouched benchmarks
⏩ 10 skipped benchmarks1


Comparing 04-24-perf_devtools (692e373) with main (fb0d3b6)

Open in CodSpeed

Footnotes

  1. 10 benchmarks were skipped, so the baseline results were used instead. If they were deleted from the codebase, click here and archive them to remove them from the performance reports.

@IWANABETHATGUY

IWANABETHATGUY commented Apr 25, 2026

Copy link
Copy Markdown
Member Author

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.

IWANABETHATGUY commented May 5, 2026

Copy link
Copy Markdown
Member Author

Merge activity

  • May 5, 6:25 AM UTC: The merge label 'graphite: merge-when-ready' was detected. This PR will be added to the Graphite merge queue once it meets the requirements.
  • May 5, 6:26 AM UTC: IWANABETHATGUY added this pull request to the Graphite merge queue.
  • May 5, 6:34 AM UTC: Merged by the Graphite merge queue.

## 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
@graphite-app
graphite-app Bot force-pushed the 04-24-perf_devtools branch from 692e373 to 2b23515 Compare May 5, 2026 06:26
@graphite-app
graphite-app Bot merged commit 2b23515 into main May 5, 2026
33 checks passed
@graphite-app
graphite-app Bot deleted the 04-24-perf_devtools branch May 5, 2026 06:34
@rolldown-guard rolldown-guard Bot mentioned this pull request May 6, 2026
@rolldown-guard rolldown-guard Bot mentioned this pull request May 7, 2026
@shulaoda shulaoda mentioned this pull request May 7, 2026
shulaoda added a commit that referenced this pull request May 7, 2026
## [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
pull Bot pushed a commit to olrtg/rolldown that referenced this pull request May 7, 2026
## [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]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[Bug]: use devtools option make time increases seriously

2 participants