From b524d547d50f009b6c2ecce09387c0c5ea59b25c Mon Sep 17 00:00:00 2001 From: l0ng-ai <24760907+l0ng-ai@users.noreply.github.com> Date: Fri, 6 Nov 2026 23:32:27 +0800 Subject: [PATCH] perf(run): show a flood of console output at most every 50 ms While a process printed thousands of lines a second, the Run console appended, re-rendered and laid out on every frame, so typing in an editor meanwhile missed the next frame 35% of the time. A line after a quiet spell still shows on the next frame; a flood now updates the console at ~20 Hz, and typing during it misses 2-5% (p50 16 -> 9.7 ms) with the output done as fast as before. The performance harness gets a scenario for it: 50,000 log lines at 200 a frame (a dev and perf build action, run.sampleOutput) while typing. --- perf/budgets.json | 6 ++ perf/scenarios.ts | 41 ++++++++++++++ src/features/run/consoleFlush.test.ts | 28 +++++++++ src/features/run/index.ts | 16 ++++++ src/features/run/store.ts | 82 ++++++++++++++++++++++++++- src/workbench/perfProbe.ts | 4 +- 6 files changed, 173 insertions(+), 4 deletions(-) create mode 100644 src/features/run/consoleFlush.test.ts diff --git a/perf/budgets.json b/perf/budgets.json index a362fa397..31f13c7e7 100644 --- a/perf/budgets.json +++ b/perf/budgets.json @@ -40,6 +40,12 @@ "completion.arrowMissedFramePct": 2, "completion.tbtMs": 50, + "consoleOutput.streamMs": 4600, + "consoleOutput.droppedFramesPct": 2, + "consoleOutput.keyP95Ms": 20, + "consoleOutput.keyMissedFramePct": 10, + "consoleOutput.tbtMs": 50, + "keyRepeat.p95Ms": 20, "keyRepeat.maxMs": 33, "keyRepeat.missedFramePct": 2, diff --git a/perf/scenarios.ts b/perf/scenarios.ts index 1022c6cdc..951e9ce6c 100644 --- a/perf/scenarios.ts +++ b/perf/scenarios.ts @@ -152,6 +152,46 @@ const completion: Scenario = { }, }; +/** + * A process printing 50,000 log lines (stack frames among them) at 200 lines a + * frame (~4 s) into the Run console, while the user types in an editor: the + * console must keep up and the editor must stay responsive. + */ +const consoleOutput: Scenario = { + id: "consoleOutput", + title: "Type while the Run console streams 50k lines", + async run(h) { + await h.openFile(SAMPLE); + const st = await h.editorState(); + await h.setCursor(Math.floor((st?.length ?? 0) / 2)); + await h.page.keyboard.press("End"); + await h.page.keyboard.press("Enter"); + const refresh = await h.refreshMs(); + const t0 = await h.now(); + await h.inPage((p) => p.startFrames()); + const streamMs = h.page.evaluate(async () => { + const w = window as never as { __openideaPerf: { runAction(id: string, arg?: unknown): Promise } }; + const started = performance.now(); + await w.__openideaPerf.runAction("run.sampleOutput", { lines: 50_000, perFrame: 200 }); + return performance.now() - started; + }); + // The console takes focus with it; type back in the editor while it streams. + await h.page.waitForTimeout(100); + await h.setCursor((await h.editorState())?.head ?? 0); + const keys = await h.typeMeasured(TYPED.slice(0, 40), 70); + const total = await streamMs; + const frames = await h.inPage((p) => p.stopFrames()); + await h.inPage((p) => p.waitShown("body", "processed order #49998", 5_000)); + return { + // 250 frames of output at the display rate is the floor. + streamMs: total, + ...frameSummary(frames, refresh), + ...keySummary(keys, refresh, "key"), + tbtMs: totalBlockingTime(await h.longTasksSince(t0)), + }; + }, +}; + /** Held key: auto-repeat at ~30 Hz must never fall behind. */ const keyRepeat: Scenario = { id: "keyRepeat", @@ -412,6 +452,7 @@ export const SCENARIOS: Scenario[] = [ typingLarge, typingAngular, completion, + consoleOutput, keyRepeat, scroll, tabs, diff --git a/src/features/run/consoleFlush.test.ts b/src/features/run/consoleFlush.test.ts new file mode 100644 index 000000000..d89385cef --- /dev/null +++ b/src/features/run/consoleFlush.test.ts @@ -0,0 +1,28 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import { startSampleOutput, useRun } from "./store"; + +describe("console output", () => { + afterEach(() => vi.useRealTimers()); + + it("shows a flood of output at most every 50 ms, a first line on the next frame", async () => { + vi.useFakeTimers({ + toFake: ["setTimeout", "clearTimeout", "requestAnimationFrame", "cancelAnimationFrame", "performance"], + }); + const updates: number[] = []; + const stop = useRun.subscribe((s, prev) => { + if (s.versions !== prev.versions) updates.push(performance.now()); + }); + // 60 frames of output, 10 lines each. + const done = startSampleOutput(600, 10); + await vi.advanceTimersByTimeAsync(2_000); + await done; + stop(); + const session = useRun.getState().sessions.at(-1)!; + expect(session.status).not.toBe("running"); + // Creating the session; the first lines (enqueued a frame later) on the next frame; then every ≥ 50 ms. + expect(updates[1]! - updates[0]!).toBeLessThanOrEqual(34); + const gaps = updates.slice(2, -2).map((t, i) => t - updates[i + 1]!); + expect(Math.min(...gaps)).toBeGreaterThanOrEqual(50); + expect(updates.length).toBeLessThan(30); + }); +}); diff --git a/src/features/run/index.ts b/src/features/run/index.ts index 9bb61ea57..d4a249b96 100644 --- a/src/features/run/index.ts +++ b/src/features/run/index.ts @@ -72,6 +72,7 @@ import { selectConfig, selectedConfig, startRun, + startSampleOutput, stopSession, trackRecentConfigurations, useRun, @@ -278,6 +279,21 @@ const useEditConfigsOpen = () => useRun((s) => s.editorOpen); export function activate(): () => void { const disposers: Array<() => void> = [ + // The performance harness (`perf/`): a console streaming generated output. + import.meta.env.DEV || import.meta.env.MODE === "perf" + ? registerActions([ + { + id: "run.sampleOutput", + title: "Stream Sample Output", + category: "Run", + hidden: true, + run: async ({ arg }) => { + const { lines = 20_000, perFrame = 200 } = (arg ?? {}) as { lines?: number; perFrame?: number }; + await startSampleOutput(lines, perFrame); + }, + }, + ]) + : () => {}, registerToolWindow({ id: "run", title: "Run", diff --git a/src/features/run/store.ts b/src/features/run/store.ts index 6c542050c..3c7099228 100644 --- a/src/features/run/store.ts +++ b/src/features/run/store.ts @@ -90,8 +90,13 @@ interface SessionRuntime { /** Machine-readable stdout (`go test -json`, `--teamcity`): fed to the parser, shown decoded. */ stdout: TestStdout | null; queue: OutputChunk[]; - /** rAF id while the page is visible, timeout id while hidden (rAF pauses in background tabs). */ + /** + * rAF id while the page is visible, timeout id while hidden (rAF pauses in + * background tabs) or while waiting out `FLUSH_INTERVAL`. + */ flushHandle: { raf: number } | { timeout: number } | null; + /** When output was last shown (`performance.now()`). */ + flushedAt: number; /** Bumped per start so output from a previous run in the same tab is ignored. */ generation: number; /** Called with every complete output line (e.g. waiting for a JDWP agent). */ @@ -494,6 +499,7 @@ function flush(sessionId: string) { if (!rt) return; cancelFlush(rt); if (rt.queue.length === 0) return; + rt.flushedAt = performance.now(); const chunks = rt.queue.splice(0); for (const c of chunks) { const text = c.kind === "stdout" && rt.stdout ? rt.stdout.feed(c.text) : c.text; @@ -514,12 +520,27 @@ function enqueue(sessionId: string, chunk: OutputChunk) { // rAF pauses in background tabs; a timeout keeps consuming output so it doesn't // pile up until the console is shown again (issue #319: the console "kept // scrolling" the previous run's backlog after switching back to it). + const wait = FLUSH_INTERVAL - (performance.now() - rt.flushedAt); rt.flushHandle = document.hidden ? { timeout: window.setTimeout(() => flush(sessionId), 100) } - : { raf: requestAnimationFrame(() => flush(sessionId)) }; + : wait > 0 + ? { + timeout: window.setTimeout( + () => (rt.flushHandle = { raf: requestAnimationFrame(() => flush(sessionId)) }), + wait, + ), + } + : { raf: requestAnimationFrame(() => flush(sessionId)) }; } } +/** + * Shortest time between console updates. A line after a quiet spell shows on the + * next frame; a flood is shown at ~20 Hz instead of every frame, which kept + * typing elsewhere from fitting in a frame (35% missed while 12k lines/s stream). + */ +const FLUSH_INTERVAL = 50; + function cancelFlush(rt: SessionRuntime) { if (rt.flushHandle === null) return; if ("raf" in rt.flushHandle) cancelAnimationFrame(rt.flushHandle.raf); @@ -587,6 +608,7 @@ function newRuntime(config: RunConfig): SessionRuntime { }), queue: [], flushHandle: null, + flushedAt: -Infinity, generation: 0, lineListeners: [], input: "", @@ -1270,3 +1292,59 @@ export function modifyTemporary(config: RunConfig) { editDirty: adopted.detected === false, }); } + +const SAMPLE_LINES = [ + (i: number) => + `2026-11-05 10:42:${String(i % 60).padStart(2, "0")}.${String(i % 1000).padStart(3, "0")} INFO 4242 --- [nio-8080-exec-${i % 10}] c.a.orders.service.OrderService : processed order #${i} in ${i % 97} ms`, + (i: number) => `\tat com.acme.orders.service.OrderService.process(OrderService.kt:${(i % 300) + 1})`, + (i: number) => + `2026-11-05 10:42:01.${String(i % 1000).padStart(3, "0")} DEBUG 4242 --- [ main] o.s.web.servlet.DispatcherServlet : GET "/api/orders/${i}", parameters={}`, +]; + +/** + * Development and the performance harness only: a session whose console gets + * `lines` generated log lines (stack frames among them), `perFrame` per + * animation frame, as from a chatty process. Resolves once all are shown. + */ +export async function startSampleOutput(lines: number, perFrame: number): Promise { + const config: RunConfig = { + id: `sample-output-${sessionSeq + 1}`, + name: "Sample output", + kind: "shell", + command: "", + args: [], + cwd: null, + env: {}, + detected: false, + isTest: false, + debugAdapter: null, + }; + const session: RunSession = { + id: `run${++sessionSeq}`, + config, + runId: null, + status: "running", + exitCode: null, + startedAt: Date.now(), + endedAt: null, + stdinClosed: true, + }; + runtimes.set(session.id, newRuntime(config)); + useRun.setState((s) => ({ sessions: [...s.sessions, session], activeSession: session.id })); + bump(session.id); + try { + toolWindowService().show("run"); + } catch { + /* no workbench (tests) */ + } + for (let i = 0; i < lines;) { + await new Promise(requestAnimationFrame); + for (const end = Math.min(lines, i + perFrame); i < end; i++) { + const line = SAMPLE_LINES[i % 20 === 19 ? 1 : i % 7 === 6 ? 2 : 0]!(i); + enqueue(session.id, { kind: i % 101 === 100 ? "stderr" : "stdout", text: `${line}\n` }); + } + } + await new Promise(requestAnimationFrame); + flush(session.id); + finishSession(session.id, 0); +} diff --git a/src/workbench/perfProbe.ts b/src/workbench/perfProbe.ts index 8c80e56c5..071664ef3 100644 --- a/src/workbench/perfProbe.ts +++ b/src/workbench/perfProbe.ts @@ -16,7 +16,7 @@ export interface PerfProbe { /** Seeds file contents for the in-memory document backend (plain-browser mode). */ seed(path: string, text: string): void; openFile(path: string): Promise; - runAction(id: string): Promise; + runAction(id: string, arg?: unknown): Promise; /** Effective keymap bindings of an action, e.g. `["Ctrl+Shift+A"]`. */ bindings(id: string): string[]; /** Moves the caret of the active editor and focuses it. */ @@ -77,7 +77,7 @@ export function installPerfProbe(): () => void { backend.files.set(path, text); }, openFile: (path) => editorService().openFile(path), - runAction: (id) => executeAction(id), + runAction: (id, arg) => executeAction(id, arg), bindings: (id) => bindingsFor(id), setCursor(offset) { const view = activeEditor()?.view;