diff --git a/docs/research/README.md b/docs/research/README.md index 3ba539ba..07707793 100644 --- a/docs/research/README.md +++ b/docs/research/README.md @@ -2,6 +2,10 @@ Research records preserve sourced investigation and distinguish observations, inferences, recommendations, and unknowns. They are not accepted Decisions or proof of runtime behavior by themselves. +## Validated investigations + +- [`WORKFLOW_DASHBOARD_REFRESH_2026-09-07.md`](WORKFLOW_DASHBOARD_REFRESH_2026-09-07.md) — repeated synchronous history loading on dashboard animation ticks, its regression boundary, and measurement limits ([#420](https://github.com/openpi-dev/openpi/issues/420)). + ## Legacy records The following records predate [`Decision 0001`](../decisions/0001-documentation-and-evidence-governance.md). They remain useful historical sources but have not been migrated to the new metadata contract as part of this change: diff --git a/docs/research/WORKFLOW_DASHBOARD_REFRESH_2026-09-07.md b/docs/research/WORKFLOW_DASHBOARD_REFRESH_2026-09-07.md new file mode 100644 index 00000000..e397e8a5 --- /dev/null +++ b/docs/research/WORKFLOW_DASHBOARD_REFRESH_2026-09-07.md @@ -0,0 +1,58 @@ +# Workflow dashboard refresh investigation + +- Status: validated at the source and regression-test boundary +- Created / verified: 2026-09-07 +- Baseline: `c8f2c13d49f2e6cd3b389dfff72ccc2eaca970c1` +- Fix boundary: the dashboard and regression tests delivered with this record +- Issue: [#420](https://github.com/openpi-dev/openpi/issues/420) +- Supersedes: none + +## Observations + +At the baseline, the dashboard's 120 ms spinner interval calls `refresh()`, +which calls `loadRunEntries()`. The loader scans persisted runs and synchronously +normalizes their records and hydrates result/transcript artifacts before filtering +by session and request time. Returning from phase detail also calls this loader. + +A live local Pi process reached approximately 101% CPU. A three-second macOS +sample found its main thread in a timer callback, with file opens, JSON parsing, +string processing and GC. The sample did not resolve JavaScript function names, +so it does not independently identify the dashboard callback. + +A read-only probe of the real loader against approximately 13 MB of local history, +using a nonmatching session and the current request time, returned no entries. +Three Node measurements were 3522, 3327 and 3952 ms. After the scoped change, +measurements were 798, 3 and 3 ms. These exploratory measurements include cache +and concurrent-load effects; they are not a controlled speedup claim or a formal +Benchmark. No provider calls were needed for the probe. + +## Reproducible regression boundary + +`tests/extensions/workflows/dashboard.test.ts` exercises the real dashboard with +Node mock timers and filesystem call observation. Against the baseline, ten +animation ticks plus returning from detail read history eleven times, and opening +an overview read both side artifacts. With the fix, steady ticks and navigation +perform neither historical reads nor directory scans. A persisted transcript is +loaded when opened and reused on render. Completion is still read once from the +canonical record after its live owner leaves; newly retained runs are surfaced, +and excluded old retention entries are not retried on every tick. + +The fix caches history only for the dashboard instance lifetime, uses live +in-memory projections for progress, and filters raw record metadata before +normalizing unrelated history. Reopening the dashboard refreshes the disk snapshot. +Reports explicitly hydrate their selected run. No persisted format or model tool +contract changes. + +## Interpretation and limits + +Synchronous multi-second work at animation cadence is sufficient to block the +shared JavaScript thread and delay keyboard handling. Separating stable animation +from historical loading removes this reproduced cause. It does not establish that +all ordinary conversation-view lag has the same cause. + +Initial history discovery still reads workflow metadata synchronously once; +opening a large historical transcript can still incur a one-time load. Historical +changes from other processes become visible on reopening the dashboard. This +record does not claim real-terminal acceptance after reload, release publication, +or elimination of every performance bottleneck. Private sessions, transcripts and +raw process samples remain outside the repository. diff --git a/extensions/workflows/dashboard.ts b/extensions/workflows/dashboard.ts index dc214b19..eb9e483a 100644 --- a/extensions/workflows/dashboard.ts +++ b/extensions/workflows/dashboard.ts @@ -143,18 +143,54 @@ export function readPersistedWorkflowDetails( runId: string, options: ReadPersistedRunOptions = {}, ): WorkflowDetails | undefined { - let details: WorkflowDetails | undefined; + const details = normalizeReadRecord( + runId, + readPersistedWorkflowRecord(runId), + ); + if (!details) return undefined; + if (options.hydrateArtifacts) hydrateRunArtifacts(runId, details); + return details; +} + +function normalizeReadRecord(runId: string, raw: unknown) { + try { + return normalizePersistedWorkflowDetails(runId, raw); + } catch { + return undefined; + } +} + +function readPersistedWorkflowRecord(runId: string) { try { const raw: unknown = JSON.parse( fs.readFileSync(path.join(runsDir(), runId, "workflow.json"), "utf8"), ); - details = normalizePersistedWorkflowDetails(runId, raw); + return raw && typeof raw === "object" + ? (raw as Record) + : undefined; } catch { return undefined; } - if (!details) return undefined; - if (options.hydrateArtifacts) hydrateRunArtifacts(runId, details); - return details; +} + +function matchesRunScope( + record: { startedAt?: unknown; finishedAt?: unknown; sessionId?: unknown }, + runId: string, + sessionId: string, + referencedRunIds: ReadonlySet, + startedSince: number, + fromRetention = false, +) { + const touchedAt = Math.max( + typeof record.startedAt === "number" ? record.startedAt : 0, + typeof record.finishedAt === "number" ? record.finishedAt : 0, + ); + return ( + touchedAt >= startedSince && + (fromRetention || + record.sessionId === sessionId || + referencedRunIds.has(runId)) + ); } function isWorktreeCleanup( @@ -581,27 +617,41 @@ export function loadRunEntries( retained: ReadonlyMap = new Map(), ): RunEntry[] { const entries: RunEntry[] = []; - const runIds = new Set([...listPersistedRunIds(), ...retained.keys()]); + const runIds = new Set([ + ...listPersistedRunIds(), + ...retained.keys(), + ...active.keys(), + ]); for (const runId of runIds) { const live = active.get(runId); if (live) { entries.push({ runId, details: live, live: true }); continue; } - const persisted = readPersistedWorkflowDetails(runId, { - hydrateArtifacts: true, - }); + // Reject unrelated history before normalizing potentially large inline + // transcripts. Side artifacts belong to explicit detail navigation. + const raw = readPersistedWorkflowRecord(runId); + if ( + raw && + !matchesRunScope(raw, runId, sessionId, referencedRunIds, startedSince) + ) { + continue; + } + const persisted = normalizeReadRecord(runId, raw); const retainedDetails = retained.get(runId); const details = persisted ?? retainedDetails; if (!details) continue; const fromRetention = persisted === undefined && retainedDetails !== undefined; - const touchedAt = Math.max(details.startedAt, details.finishedAt ?? 0); if ( - touchedAt < startedSince || - (!fromRetention && - details.sessionId !== sessionId && - !referencedRunIds.has(runId)) + !matchesRunScope( + details, + runId, + sessionId, + referencedRunIds, + startedSince, + fromRetention, + ) ) { continue; } @@ -718,6 +768,9 @@ type DetailFocus = "phases" | "agents"; export class WorkflowDashboard { private view: View = "list"; private entries: RunEntry[] = []; + private historyLoaded = false; + private seenRetainedRunIds = new Set(); + private hydratedRunIds = new Set(); private listIndex = 0; private phaseIndex = 0; private agentIndex = 0; @@ -826,13 +879,68 @@ export class WorkflowDashboard { private refresh() { const selected = this.entries[this.listIndex]?.runId; - this.entries = loadRunEntries( - this.getActive(), - this.sessionId, - this.referencedRunIds, - this.startedSince, - this.getRetained(), - ); + const active = this.getActive(); + const retained = this.getRetained(); + if (!this.historyLoaded) { + this.entries = loadRunEntries( + active, + this.sessionId, + this.referencedRunIds, + this.startedSince, + retained, + ); + this.historyLoaded = true; + } else { + // Animation ticks reuse historical projections. Only a newly settled run + // needs one canonical read; stable frames never scan or reread history. + const entries = new Map( + this.entries.map((entry) => [entry.runId, entry]), + ); + const settledIds = new Set([ + ...this.entries + .filter((entry) => entry.live && !active.has(entry.runId)) + .map((entry) => entry.runId), + ...[...retained.keys()].filter( + (runId) => + !this.seenRetainedRunIds.has(runId) && + !entries.has(runId) && + !active.has(runId), + ), + ]); + for (const runId of settledIds) { + const persisted = readPersistedWorkflowDetails(runId); + const details = + persisted ?? retained.get(runId) ?? entries.get(runId)?.details; + if (!details) continue; + if ( + !matchesRunScope( + details, + runId, + this.sessionId, + this.referencedRunIds, + this.startedSince, + !persisted, + ) + ) { + entries.delete(runId); + continue; + } + // Recovery operates on a projection, never on the former live owner. + const recovered = recoverStaleWorkflowDetails({ + ...details, + agents: details.agents.map((agent) => ({ ...agent })), + }); + entries.set(runId, { runId, details: recovered, live: false }); + this.hydratedRunIds.delete(runId); + } + for (const [runId, details] of active) { + entries.set(runId, { runId, details, live: true }); + } + this.entries = [...entries.values()].sort( + (a, b) => b.details.startedAt - a.details.startedAt, + ); + } + for (const runId of retained.keys()) this.seenRetainedRunIds.add(runId); if (selected) { const index = this.entries.findIndex((e) => e.runId === selected); if (index >= 0) this.listIndex = index; @@ -847,6 +955,7 @@ export class WorkflowDashboard { ); if (refreshed) this.current = refreshed; } + if (this.view === "transcript") this.hydrateCurrent(); if (this.notice && Date.now() - this.noticeAt > NOTICE_TTL_MS) this.notice = undefined; } @@ -882,7 +991,15 @@ export class WorkflowDashboard { this.agentIndex = Math.min(this.agentIndex, Math.max(0, agents.length - 1)); } + private hydrateCurrent() { + const entry = this.current; + if (!entry || entry.live || this.hydratedRunIds.has(entry.runId)) return; + hydrateRunArtifacts(entry.runId, entry.details); + this.hydratedRunIds.add(entry.runId); + } + private saveReport() { + this.hydrateCurrent(); const entry = this.current; if (!entry) return; const target = path.join(runsDir(), entry.runId, "report.md"); @@ -1023,6 +1140,7 @@ export class WorkflowDashboard { } private openTranscriptPage() { + this.hydrateCurrent(); const transcriptAdapter = new WorkflowTranscriptAdapter(); this.view = "transcript"; this.transcriptPage = new AgentSessionPage( diff --git a/tests/extensions/workflows/dashboard.test.ts b/tests/extensions/workflows/dashboard.test.ts index 04f43f8a..67ec4d1f 100644 --- a/tests/extensions/workflows/dashboard.test.ts +++ b/tests/extensions/workflows/dashboard.test.ts @@ -1,4 +1,5 @@ import assert from "node:assert/strict"; +import fs from "node:fs"; import { chmodSync, mkdirSync, @@ -7,6 +8,7 @@ import { statSync, writeFileSync, } from "node:fs"; +import { syncBuiltinESMExports } from "node:module"; import { tmpdir } from "node:os"; import { join } from "node:path"; import test from "node:test"; @@ -931,3 +933,198 @@ test("narrator lines survive the disk round trip and are re-sanitized", () => { ); assert.equal(details?.logsDropped, 4); }); + +function performanceDashboard( + active: Map, + initialRunId?: string, + retained: Map = new Map(), + startedSince = 0, +) { + return new WorkflowDashboard( + { terminal: { rows: 30 }, requestRender() {} } as unknown as TUI, + { + fg: (_color: string, text: string) => text, + bold: (text: string) => text, + } as unknown as Theme, + { + matches: () => false, + getKeys: () => ["esc"], + } as unknown as KeybindingsManager, + () => active, + SESSION, + new Set(), + startedSince, + () => {}, + initialRunId, + undefined, + () => retained, + ); +} + +test("animation and navigation reuse history while live progress and settlement remain visible", (t) => { + t.mock.timers.enable({ apis: ["setInterval"] }); + const runId = "wf_ab120"; + const details = { + ...retainedRun(runId, Date.now()), + status: "running" as const, + }; + delete details.finishedAt; + writeRun(runId, details.startedAt); + const active = new Map([[runId, details]]); + const dashboard = performanceDashboard(active); + const read = t.mock.method(fs, "readFileSync"); + const scan = t.mock.method(fs, "readdirSync"); + syncBuiltinESMExports(); + t.after(() => { + t.mock.restoreAll(); + syncBuiltinESMExports(); + }); + try { + details.name = "updated-live-name"; + for (let i = 0; i < 10; i++) { + t.mock.timers.tick(SPINNER_INTERVAL_MS); + dashboard.render(100); + } + assert.match(dashboard.render(100).join("\n"), /updated-live-name/); + dashboard.handleInput("l"); + dashboard.handleInput("h"); + assert.equal( + read.mock.callCount(), + 0, + "animation/navigation must not reread history", + ); + assert.equal( + scan.mock.callCount(), + 0, + "animation/navigation must not rescan history", + ); + + // Completion is still read from canonical disk once the live owner leaves. + writeFileSync( + join(agentDir, "workflows", runId, "workflow.json"), + JSON.stringify({ + ...details, + name: "canonical-settled-name", + status: "completed", + finishedAt: Date.now(), + }), + ); + active.delete(runId); + t.mock.timers.tick(SPINNER_INTERVAL_MS); + assert.match(dashboard.render(100).join("\n"), /canonical-settled-name/); + const readsAfterSettlement = read.mock.callCount(); + assert.equal(readsAfterSettlement, 1); + t.mock.timers.tick(SPINNER_INTERVAL_MS * 10); + assert.equal(read.mock.callCount(), readsAfterSettlement); + } finally { + dashboard.dispose(); + } +}); + +test("history overview defers artifacts until a persisted transcript is opened", (t) => { + const runId = "wf_ab121"; + const details = retainedRun(runId, Date.now()); + const dir = join(agentDir, "workflows", runId); + mkdirSync(dir, { recursive: true }); + writeFileSync( + join(dir, "workflow.json"), + JSON.stringify({ + ...details, + transcriptArtifact: "transcripts.json", + resultArtifact: "result.json", + phases: [{ title: "Work" }], + agents: [ + { + index: 1, + label: "worker", + phase: "Work", + state: "done", + startedAt: details.startedAt, + }, + ], + }), + ); + writeFileSync( + join(dir, "transcripts.json"), + JSON.stringify({ + "1": [{ role: "assistant", text: "lazy transcript evidence" }], + }), + ); + writeFileSync( + join(dir, "result.json"), + JSON.stringify("lazy result evidence"), + ); + const read = t.mock.method(fs, "readFileSync"); + syncBuiltinESMExports(); + t.after(() => { + t.mock.restoreAll(); + syncBuiltinESMExports(); + }); + const artifactReads = () => + read.mock.calls.filter((call) => + /(?:transcripts|result)\.json$/.test(String(call.arguments[0])), + ).length; + const dashboard = performanceDashboard(new Map(), runId); + try { + assert.equal( + artifactReads(), + 0, + "overview must not hydrate side artifacts", + ); + dashboard.handleInput("l"); + assert.equal( + artifactReads(), + 0, + "agent list must not hydrate side artifacts", + ); + dashboard.handleInput("l"); + assert.match(dashboard.render(100).join("\n"), /lazy transcript evidence/); + const loaded = artifactReads(); + assert.ok(loaded > 0); + dashboard.render(100); + dashboard.render(100); + assert.equal( + artifactReads(), + loaded, + "render must reuse the loaded transcript", + ); + } finally { + dashboard.dispose(); + } +}); + +test("retained history excluded by request time is not retried on animation ticks", (t) => { + t.mock.timers.enable({ apis: ["setInterval"] }); + const oldId = "wf_ab122"; + const liveId = "wf_ab123"; + const old = retainedRun(oldId, 1); + writeRun(oldId, 1); + const live = { ...retainedRun(liveId, 10_000), status: "running" as const }; + const retained = new Map([[oldId, old]]); + const dashboard = performanceDashboard( + new Map([[liveId, live]]), + undefined, + retained, + 5_000, + ); + const read = t.mock.method(fs, "readFileSync"); + syncBuiltinESMExports(); + t.after(() => { + t.mock.restoreAll(); + syncBuiltinESMExports(); + }); + try { + t.mock.timers.tick(SPINNER_INTERVAL_MS * 10); + assert.equal(read.mock.callCount(), 0); + // A run may finish entirely between frames; retention must surface it. + const finished = retainedRun("wf_ab124", 11_000); + retained.set(finished.runId, finished); + t.mock.timers.tick(SPINNER_INTERVAL_MS); + assert.match(dashboard.render(100).join("\n"), /wf_ab124/); + assert.equal(read.mock.callCount(), 1); + t.mock.timers.tick(SPINNER_INTERVAL_MS * 10); + assert.equal(read.mock.callCount(), 1); + } finally { + dashboard.dispose(); + } +});