Skip to content

Wait for bursts of external writes before writing the Terminal status - #2170

Open
vzaidman wants to merge 1 commit into
react:mainfrom
vzaidman:vzaidman/terminal-external-write-bursts
Open

vzaidman wants to merge 1 commit into
react:mainfrom
vzaidman:vzaidman/terminal-external-write-bursts

Conversation

@vzaidman

@vzaidman vzaidman commented Nov 4, 2026 •

Copy link
Copy Markdown
Contributor

Summary

When output is written outside of Terminal (e.g. console.log) in a burst, a status update can land between the burst's lines. In a TTY it can't be erased there, so copies of the status are left scattered in the output.

  • Before writing the status, Terminal waits until no output is written outside of it for 333ms (EXTERNAL_WRITES_QUIET_MS), in interactive and non-interactive terminals. Outside output is detected through the stream's bytesWritten. Without outside output, the status is written synchronously. flush() skips the wait.
  • Status writes wait on a delay promise set after each write: 33ms in a TTY, 3500ms otherwise. flush() ends the delay early.
  • Status delay timers are unreferenced, so they don't keep the process alive. An ongoing status update is flushed on beforeExit, so the latest status is still written and waitForUpdates() resolves.
  • lodash.throttle is removed from metro-core and metro:
    • Terminal limits non-TTY status lines through the same status delay.
    • TerminalReporter updates bundle progress on each bundle_transform_progressed event; Terminal limits the redraws. The bundle_transform_progressed_throttled event type is removed from TerminalReportableEvent.
  • The status is erased with ANSI escape sequences written through Terminal's own write, so every write tracks its completion and the bytes written after it. node:readline is no longer used.
  • isUpdating and hasPendingUpdate are removed: an update is ongoing while #updatePromise is set, and pending while the written status differs from the latest one.

The performance impact was measured with the benchmark in #2171, which builds a generated app and supports a base patch applied to every variant (results below).

Changelog: [Breaking] Terminal no longer prints the status in the middle of bursts of output written outside of it, and bundle_transform_progressed_throttled is removed from TerminalReportableEvent

Test plan

  • New test "writes the status after a burst of external writes" fails before this change, with a 33ms quiet period, and without non-TTY outside output detection, and passes after.
  • New test "flush does not wait for the next status update" fails when flush() doesn't end the status delay.
  • New test "flushes the pending status before the process exits" fails without the beforeExit listener.
  • New TerminalReporter test "shows the latest bundle transform progress" fails with the throttled reporter.
  • Terminal-test.js uses fake timers.
  • yarn jest packages/metro-core packages/metro/src/lib
  • yarn flow check, yarn eslint packages/metro-core/src packages/metro/src/lib, yarn verify-api-snapshots

Benchmark

node scripts/benchmark-patches/benchmark-patches.js bundling_speed --runs=10, with a base.patch that makes metro build log 3 lines per transformed module (30,000 lines per build, interleaved with progress updates), and this PR's Terminal.js and TerminalReporter.js changes as the variant patch. Measured on 94cc963 (these files are unchanged on the base of this PR):

Bundle Variant Wall (s) Wall Δ CPU (s) CPU Δ Size (bytes) Same as unpatched
app-prod unpatched 8.2 ± 0.6 69.1 ± 3.7 600,199 yes
app-prod terminal-external-write-bursts 5.9 ± 0.7 -28.38% (t -7.9) 68.5 ± 3.3 -0.86% (t -0.4) 600,199 yes
app-dev unpatched 8.2 ± 0.4 54.3 ± 2.2 1,447,772 yes
app-dev terminal-external-write-bursts 5.1 ± 0.7 -37.28% (t -12.0) 55.7 ± 2.7 +2.69% (t 1.3) 1,447,772 yes

Values are mean ± sample sd over 10 runs per variant. t is Welch's t vs unpatched.

The saving is a roughly flat 2-3s per build, not faster bundling: the process no longer waits for status timers before exiting (on main, the trailing lodash.throttle timer, up to 3.5s after the last status line in non-interactive output). The generated app builds in about 5s, so the percentages are large. Longer builds, like real apps, save about the same seconds, which is a much smaller share of their wall time. CPU time doesn't change significantly, and bundles are byte-identical.

base.patch
diff --git a/packages/metro/src/commands/build.js b/packages/metro/src/commands/build.js
index af858666c..ee2f45492 100644
--- a/packages/metro/src/commands/build.js
+++ b/packages/metro/src/commands/build.js
@@ -133,6 +133,11 @@ export default (): CommandModule => ({
         transformedFileCount: number,
         totalFileCount: number,
       ): void => {
+        for (let i = 0; i < 3; i++) {
+          console.log(
+            `transformed ${transformedFileCount}/${totalFileCount} (${i})`,
+          );
+        }
         updateReporter.update({
           buildID: '$',
           type: 'bundle_transform_progressed',

@meta-cla meta-cla Bot added the CLA Signed This label is managed by the Facebook bot. Authors need to sign the CLA before a PR can be reviewed. label Nov 4, 2026
@vzaidman
vzaidman force-pushed the vzaidman/terminal-external-write-bursts branch 2 times, most recently from 5b00d8a to 286024f Compare November 4, 2026 20:16
@vzaidman
vzaidman marked this pull request as ready for review November 4, 2026 20:21
Summary:
When output was written outside of `Terminal` (e.g. `console.log`) in a burst, a status update could land between the burst's lines. In a TTY it can't be erased there, so copies of the status were left scattered in the output.

- Before writing the status, `Terminal` waits until no output is written outside of it for 333ms (`EXTERNAL_WRITES_QUIET_MS`), in interactive and non-interactive terminals. Outside output is detected through the stream's `bytesWritten`. Without outside output, the status is written synchronously. `flush()` skips the wait.
- Status writes wait on a delay promise set after each write: 33ms in a TTY, 3500ms otherwise. `flush()` ends the delay early.
- Status delay timers are unreferenced, so they don't keep the process alive. An ongoing status update is flushed on `beforeExit`, so the latest status is still written and `waitForUpdates()` resolves.
- `lodash.throttle` is removed from `metro-core` and `metro`:
  - `Terminal` limits non-TTY status lines through the same status delay.
  - `TerminalReporter` updates bundle progress on each `bundle_transform_progressed` event; `Terminal` limits the redraws. The `bundle_transform_progressed_throttled` event type is removed from `TerminalReportableEvent`.
- The status is erased with ANSI escape sequences written through `Terminal`'s own write, so every write tracks its completion and the bytes written after it. `node:readline` is no longer used.
- `isUpdating` and `hasPendingUpdate` are removed: an update is ongoing while `#updatePromise` is set, and pending while the written status differs from the latest one.

`metro build` no longer waits for status timers before exiting: on a generated app of 5,000 modules whose build logs 3 lines per transformed module, wall time drops by 28% in prod and 37% in dev (about 2-3s, the trailing `lodash.throttle` timer on `main`), with no significant CPU change and byte-identical bundles.

Changelog: [Breaking] Terminal no longer prints the status in the middle of bursts of output written outside of it, and `bundle_transform_progressed_throttled` is removed from `TerminalReportableEvent`

Test Plan:
- New test "writes the status after a burst of external writes" fails before this change, with a 33ms quiet period, and without non-TTY outside output detection, and passes after.
- New test "flush does not wait for the next status update" fails when `flush()` doesn't end the status delay.
- New test "flushes the pending status before the process exits" fails without the `beforeExit` listener.
- New `TerminalReporter` test "shows the latest bundle transform progress" fails with the throttled reporter.
- `Terminal-test.js` uses fake timers.
- `yarn jest packages/metro-core packages/metro/src/lib`
- `yarn flow check`, `yarn eslint packages/metro-core/src packages/metro/src/lib`, `yarn verify-api-snapshots`
- `node scripts/benchmark-patches/benchmark-patches.js bundling_speed --runs=10`
@vzaidman
vzaidman force-pushed the vzaidman/terminal-external-write-bursts branch from 286024f to bd0c69d Compare November 4, 2026 20:22
@vzaidman
vzaidman requested a review from robhogan November 4, 2026 20:23
@vzaidman
vzaidman requested a review from huntie November 4, 2026 20:23
@vzaidman

vzaidman commented Nov 4, 2026 •

Copy link
Copy Markdown
Contributor Author

@robhogan how did you benchmark #2162? Could you please benchmark this as well? Maybe even add it to the benchmarking script?

@github-actions

github-actions Bot commented Nov 4, 2026

Copy link
Copy Markdown

Metro review: Changes suggested

Risk: medium · Commit: bd0c69d · 13 commands run

This PR holds Terminal status writes until outside output has been quiet for 333ms, and replaces lodash.throttle with an unreferenced status delay plus a beforeExit flush. The burst fix, exit flush and dependency removal work as described, and the 3.5s exit delay is gone. The quiet wait has no upper bound and also counts Terminal's own writes, so progress can stay hidden for as long as output continues, including output from terminal.log after a single outside line.

Findings

Verified
  • ✅ yarn jest --no-watchman packages/metro-core packages/metro/src/lib — 24 suites, 245 tests
  • ✅ yarn typecheck — Flow: no errors
  • ✅ yarn eslint packages/metro-core/src packages/metro/src/lib
  • ✅ yarn verify-api-snapshots — 18 snapshots verified
  • ✅ yarn jest --no-watchman packages/metro-core/src/__tests__/Terminal-test.js (quiet period 33ms, no endEarly in flush, no beforeExit listener; applied together) (failed as expected) — Burst test failed in both TTY modes; flush and beforeExit tests failed in one mode each. Mutations were not isolated. Reverted by hand: 33/33 pass.
  • ✅ yarn jest --no-watchman packages/metro-core/src/__tests__/TerminalReviewRepro-test.js (head) (failed as expected) — Sustained-output and own-logs repros fail; own-logs control passes.
  • ✅ yarn jest --no-watchman packages/metro-core/src/__tests__/TerminalReviewRepro-test.js (base) — Same two scenarios pass on base.
  • ✅ node repro/scenario.js <checkout> exitFlush (stdout piped, base and head) — Latest status is written on natural exit on both.
  • ✅ node repro/scenario.js <checkout> exitAfterStatus (stdout piped, base and head) — Exit at 3502ms on base and 0ms on head in a single run, confirming the trailing timer explanation.
  • ✅ node repro/scenario.js <checkout> sustained (stdout piped, base and head) (failed as expected) — Head wrote no progress status across 25 updates; base wrote one.
  • ✅ node bench/reporterEvent.js <base> <head> 10
  • ✅ node bench/buildWall.js <base> <head> 10 bench/out (run twice; second run reported) — Same stdout line count and bundle length on both sides; bundle contents were not compared byte for byte.
  • ✅ yarn@1.22.22 install --frozen-lockfile --ignore-scripts (package_manager, head) — yarn.lock is consistent after removing lodash.throttle.

Benchmarks (base vs this PR)

Benchmark Base This PR Change
metro build of the basic_bundle fixture, stdout piped 8353ms (4035-16591) 1164ms (562-5035) no significant change
20,000 progress events through TerminalReporter, non-TTY 1.0ms (0.9-3.6) 159ms (81-1022) about 8µs more per event
20,000 progress events through TerminalReporter, TTY 1.8ms (0.9-3.6) 281ms (148-1578) about 14µs more per event
Method
  • metro build of the basic_bundle fixture, stdout piped: Integration basic_bundle fixture, 10 rounds per side, ABAB, median and range. Ranges overlap on a noisy machine, with a large order effect. The paired base-minus-head median of 3503ms fits the exit-timer explanation, slightly above the PR's 2-3s. Script: bench/buildWall.js. The PR's 30,000-line logging patch was not applied.
  • 20,000 progress events through TerminalReporter, non-TTY: Real TerminalReporter and Terminal on a fake net.Socket stream, 10 rounds per side, ABAB, a fresh process per run with one warm-up pass, median and range. Base's 100ms throttled updates never fire in this loop, so its cost is understated. Script: bench/reporterEvent.js.
  • 20,000 progress events through TerminalReporter, TTY: Same as the non-TTY run, on a fake tty.WriteStream with 120 columns. Base's 100ms throttled updates never fire in this loop, so its cost is understated. About 0.3s of main-thread time per 20,000 events, which is minor for builds of that size. Script: bench/reporterEvent.js.

Not run: No real TTY: running under a pty with script was denied by the session's permission policy, so TTY behavior used the test suite's fake tty.WriteStream, and erase sequences weren't checked on a real terminal. Windows wasn't checked (no machine available). The #2171 benchmark isn't in this checkout, so the PR's table and 30,000-line patch weren't reproduced. Integration tests outside the changed areas weren't run. package.json and yarn.lock changes need a Meta import (needs-meta-import).

Automated review by Claude. Advisory only: it never approves or blocks, and a maintainer makes the call.

return undefined;
}

return this.#delayStatus(EXTERNAL_WRITES_QUIET_MS).then(() =>

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should fix · The quiet wait has no upper bound, so sustained outside output hides the status indefinitely

#waitForExternalWritesToStop keeps re-arming the 333ms delay for as long as the byte count changes, with no ceiling. Any outside writer that logs more often than every 333ms therefore blocks all status updates until it stops or flush() is called.

Failure case: a TTY, with one outside line every 200ms and bundling progress updating alongside it. On base, the progress status is written throughout. On head, no progress is written at all during the 60s simulated run, so the terminal looks hung. The PR's own benchmark patch has this shape: it logs 3 lines per transformed module, so a build with that kind of logging shows no progress bar until the output pauses. On a long build, or with a middleware or plugin that logs steadily, that can last the whole session. unstable_server_menu_updated statuses go through the same path. A plain waitForUpdates() caller also stays blocked for that time, while flush() does not.

Suggested fix: cap the total wait, for example by writing the status anyway once it has been held for a few seconds. A stranded copy now and then is a better failure than no progress at all. Add a test with outside writes that never stop.

Reproduced: Repro packages/metro-core/src/__tests__/TerminalReviewRepro-test.js, 'sustained external writes': head fails with Expected: > 0, Received: 0 progress writes over 300 writes at 200ms intervals; the same scenario passes on base. A real process on a pipe (repro/scenario.js sustained) printed no progress line on head across 25 updates over 5s; base printed one. · id 5a6c4169

}

return this.#delayStatus(EXTERNAL_WRITES_QUIET_MS).then(() =>
this.#waitForExternalWritesToStop(currentBytesWritten),

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should fix · Terminal's own writes count as outside output once the quiet wait has started

The first check compares against #bytesWrittenAfterLastWrite, which excludes Terminal's own writes. The recursive call instead compares against the currentBytesWritten captured before the delay, and that total includes anything terminal.log wrote during the delay. Once one outside write has started the wait, Terminal's own logs keep extending it, which contradicts the method's doc comment and the PR description ("no output is written outside of it").

Failure case: a TTY, one console.log line, then terminal.log every 100ms, as with client_log or worker_stdout_chunk traffic during a build. No status is written for the whole 10s run. The control without the outside line shows the status normally, so the single line is what hides it.

Suggested fix: measure outside bytes separately from Terminal's own. For example, in #write, add getBytesWritten() - #bytesWrittenAfterLastWrite to an #externalBytesWritten counter before writing, and have the wait compare that counter.

Reproduced: Repro TerminalReviewRepro-test.js, "Terminal's own logs don't extend the external quiet period": head fails with Expected: > 0, Received: 0, the control 'own logs alone' passes on head, and the same scenario passes on base. · id b4814541

break;

case 'bundle_transform_progressed_throttled':
case 'bundle_transform_progressed':

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit · Expo CLI's bundling progress events depend on the removed throttled event

The [Breaking] changelog entry covers the type removal, but a known consumer depends on the runtime event too. @expo/cli@58.1.19 subclasses TerminalReporter, and its MetroTerminalReporter.#captureLog only updates its bundle spans and emits bundling:progress on bundle_transform_progressed_throttled. Metro no longer emits that event, so once Expo moves to this Metro version, those events stop without any error.

Nothing breaks today, because @expo/metro@latest pins metro 0.87.1, and the status bar itself should keep working through the base class. Subclass _log overrides also now run on every progress event instead of at most every 100ms.

Suggested fix: give the Expo maintainers a heads-up before this ships, or say in the changelog that subclasses should handle bundle_transform_progressed instead.

Evidence: Read build/src/start/server/metro/MetroTerminalReporter.js:364 and TerminalReporter.js:87 in the @expo/cli@58.1.19 tarball from npm, and checked the pin with npm view @expo/metro@latest dependencies. Not run against this PR's Metro. · id 2c40d144

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

CLA Signed This label is managed by the Facebook bot. Authors need to sign the CLA before a PR can be reviewed. needs-meta-import

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants