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.
Цей коміт міститься в:
l0ng-ai committed 2026-11-06 23:32:27 +08:00
1 джерело f33b56b92b
коміт b524d547d5
6 files changed
+173 -4

No files matched your search

+6
Переглянути файл
@@ -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,
+41
Переглянути файл
@@ -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<boolean> } };
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,
+28
Переглянути файл
@@ -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);
});
});
+16
Переглянути файл
@@ -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",
+80 -2
Переглянути файл
@@ -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<void> {
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);
}
+2 -2
Переглянути файл
@@ -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<void>;
runAction(id: string): Promise<boolean>;
runAction(id: string, arg?: unknown): Promise<boolean>;
/** 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;