From 656fbbce252badec07b2b3ec2f3faf81c119f2de Mon Sep 17 00:00:00 2001 From: Henning Dieterichs Date: Mon, 4 May 2026 16:30:48 +0200 Subject: [PATCH] Uses full dark modern theme for component fixtures & implements improved time travel scheduler --- src/vs/base/common/async.ts | 5 + .../base/test/common/executionGraph.test.ts | 158 +++++ src/vs/base/test/common/executionGraph.ts | 475 ++++++++++++++ .../base/test/common/timeTravelScheduler.ts | 596 ++++++++++++++---- .../base/test/common/traceableTimeApi.test.ts | 330 ++++++++++ src/vs/base/test/common/traceableTimeApi.ts | 352 +++++++++++ .../browser/componentFixtures/fixtureUtils.ts | 246 ++++++-- 7 files changed, 2005 insertions(+), 157 deletions(-) create mode 100644 src/vs/base/test/common/executionGraph.test.ts create mode 100644 src/vs/base/test/common/executionGraph.ts create mode 100644 src/vs/base/test/common/traceableTimeApi.test.ts create mode 100644 src/vs/base/test/common/traceableTimeApi.ts diff --git a/src/vs/base/common/async.ts b/src/vs/base/common/async.ts index d178163e116..80da7321ed2 100644 --- a/src/vs/base/common/async.ts +++ b/src/vs/base/common/async.ts @@ -2654,3 +2654,8 @@ export class AsyncReader { return this._extendBufferPromise; } } + +export function createTimeout(ms: number, cb: () => void): IDisposable { + const t = setTimeout(cb, ms); + return toDisposable(() => clearTimeout(t)); +} diff --git a/src/vs/base/test/common/executionGraph.test.ts b/src/vs/base/test/common/executionGraph.test.ts new file mode 100644 index 00000000000..aa2ff32cb6a --- /dev/null +++ b/src/vs/base/test/common/executionGraph.test.ts @@ -0,0 +1,158 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import assert from 'assert'; +import { ensureNoDisposablesAreLeakedInTestSuite } from './utils.js'; +import { + ExecutionEvent, + ExecutionHistory, + ExecutionRoot, + renderLaneGraph, + renderSwimlanes, +} from './executionGraph.js'; + +/** + * Fluent builder for hand-crafting `ExecutionHistory` literals in tests. + * Keeps call sites short: `h.root('A')`, `h.fire(0, 'setTimeout', rootA)`, + * `h.fire(16, 'rAF', parentEvent)`. + */ +class HistoryBuilder { + readonly roots: ExecutionRoot[] = []; + readonly events: ExecutionEvent[] = []; + + root(label: string): ExecutionRoot { + const r: ExecutionRoot = { label }; + this.roots.push(r); + return r; + } + + fire(time: number, label: string, parent: ExecutionRoot | ExecutionEvent): ExecutionEvent { + const isRoot = this.roots.includes(parent as ExecutionRoot); + const root = isRoot ? (parent as ExecutionRoot) : (parent as ExecutionEvent).root; + const parentEvent = isRoot ? undefined : (parent as ExecutionEvent); + const event: ExecutionEvent = { time, label, root, parent: parentEvent }; + this.events.push(event); + return event; + } + + build(): ExecutionHistory { + return { roots: this.roots, events: this.events }; + } +} + +suite('executionGraph', () => { + ensureNoDisposablesAreLeakedInTestSuite(); + + test('renderSwimlanes: empty history', () => { + assert.strictEqual(renderSwimlanes({ roots: [], events: [] }), '(empty history)'); + }); + + test('renderSwimlanes: single root, linear chain', () => { + const h = new HistoryBuilder(); + const A = h.root('A'); + const t0 = h.fire(0, 'setTimeout', A); + const t1 = h.fire(16, 'rAF', t0); + h.fire(32, 'rAF', t1); + + // Slot-based indentation: all events are last-children, so all + // share slot 0. No visual indentation for the tree structure. + assert.strictEqual(renderSwimlanes(h.build()), [ + ' A', + ' +0ms ├─ setTimeout', + '+16ms └─ rAF', + '+32ms └─ rAF', + ].join('\n')); + }); + + test('renderSwimlanes: forest with forks across two roots', () => { + const h = new HistoryBuilder(); + const A = h.root('A'); + const B = h.root('B'); + + // A: setTimeout(+0) spawns rAF(+16) and setTimeout(+50) + // rAF(+16) -> rAF(+32) + const aT0 = h.fire(0, 'setTimeout', A); + const bT10 = h.fire(10, 'setTimeout', B); + const aRaf16 = h.fire(16, 'requestAnimationFrame', aT0); + const bRaf26 = h.fire(26, 'requestAnimationFrame', bT10); + h.fire(32, 'requestAnimationFrame', aRaf16); + h.fire(46, 'setTimeout', bRaf26); + h.fire(50, 'setTimeout', aT0); + + const out = renderSwimlanes(h.build()); + // Slot-based indentation: last-children share their parent's slot. + // B lane: bT10 at slot 0, bRaf26 (last-child) at slot 0, bT46 (last-child) at slot 0. + assert.strictEqual(out, [ + ' A B', + ' +0ms ├─ setTimeout', + '+10ms │ | ├─ setTimeout', + '+16ms │ ├─ requestAnimationFrame │', + '+26ms │ │ └─ requestAnimationFrame', + '+32ms │ └─ requestAnimationFrame │', + '+46ms │ └─ setTimeout', + '+50ms └─ setTimeout', + ].join('\n')); + }); + + test('renderSwimlanes: degenerate linked-list tree (5 nodes)', () => { + const h = new HistoryBuilder(); + const A = h.root('A'); + const e1 = h.fire(0, 'n1', A); + const e2 = h.fire(10, 'n2', e1); + const e3 = h.fire(20, 'n3', e2); + h.fire(30, 'n4', e3); + + assert.strictEqual(renderSwimlanes(h.build()), [ + ' A', + ' +0ms ├─ n1', + '+10ms └─ n2', + '+20ms └─ n3', + '+30ms └─ n4', + ].join('\n')); + }); + + test('renderLaneGraph: degenerate linked-list tree (5 nodes)', () => { + const h = new HistoryBuilder(); + const A = h.root('A'); + const e1 = h.fire(0, 'n1', A); + const e2 = h.fire(10, 'n2', e1); + const e3 = h.fire(20, 'n3', e2); + h.fire(30, 'n4', e3); + + assert.strictEqual(renderLaneGraph(h.build()), [ + '+A', + '└─╷─ [ +0ms] n1', + ' └─╷─ [ +10ms] n2', + ' └─╷─[ +20ms] n3', + ' └─[ +30ms] n4', + ].join('\n')); + }); + + test('renderLaneGraph: forest with forks across two roots', () => { + const h = new HistoryBuilder(); + const A = h.root('A'); + const B = h.root('B'); + + const aT0 = h.fire(0, 'setTimeout', A); + const bT10 = h.fire(10, 'setTimeout', B); + const aRaf16 = h.fire(16, 'requestAnimationFrame', aT0); + const bRaf26 = h.fire(26, 'requestAnimationFrame', bT10); + h.fire(32, 'requestAnimationFrame', aRaf16); + h.fire(46, 'setTimeout', bRaf26); + h.fire(50, 'setTimeout', aT0); + + assert.strictEqual(renderLaneGraph(h.build()), [ + '+A', + '└─╷─ [ +0ms] setTimeout', + ' │ +B', + ' │ └─╷─ [ +10ms] setTimeout', + ' ├───┼─╷─ [ +16ms] requestAnimationFrame', + ' │ └─┼─╷─[ +26ms] requestAnimationFrame', + ' │ └─┼─[ +32ms] requestAnimationFrame', + ' │ └─[ +46ms] setTimeout', + ' └─────────[ +50ms] setTimeout', + ].join('\n')); + }); +}); diff --git a/src/vs/base/test/common/executionGraph.ts b/src/vs/base/test/common/executionGraph.ts new file mode 100644 index 00000000000..4a9d6ca764a --- /dev/null +++ b/src/vs/base/test/common/executionGraph.ts @@ -0,0 +1,475 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +/** + * Plain, renderer-friendly description of an execution history produced by a + * traced scheduler. These types have no dependency on the tracing or + * scheduling implementation — they can be built by hand in tests or by the + * `buildHistoryFromTasks` adapter below. + */ + +export interface ExecutionRoot { + readonly label: string; +} + +export interface ExecutionEvent { + /** Relative time (e.g. ms since startTime). Must be >= 0 and non-decreasing in history order. */ + readonly time: number; + readonly label: string; + readonly root: ExecutionRoot; + /** `undefined` means this event is a direct child of its root. */ + readonly parent: ExecutionEvent | undefined; + /** Caller frame extracted from the scheduling stack trace. */ + readonly detail?: string; +} + +export interface ExecutionHistory { + /** Roots in first-appearance order (column order for renderers). */ + readonly roots: readonly ExecutionRoot[]; + /** Events in time order. */ + readonly events: readonly ExecutionEvent[]; +} + +// ----------------------------------------------------------------------------- +// Adapter: ScheduledTask[] -> ExecutionHistory +// ----------------------------------------------------------------------------- + +interface TraceLike { + readonly parent: TraceLike | undefined; + readonly root: { readonly label: string }; +} + +interface ScheduledTaskLike { + readonly time: number; + readonly source: { toString(): string; readonly stackTrace?: string }; + readonly trace?: TraceLike; +} + +/** + * A log entry to weave into the history alongside scheduled tasks. Each log is + * tagged with the trace that was current when it was emitted. + */ +export interface LogEntryLike { + readonly trace: TraceLike; + readonly message: string; +} + +/** + * Convert a list of scheduled tasks (each carrying a causal `trace`) into a + * plain `ExecutionHistory`. Untraced tasks are dropped. A task's parent event + * is the most recent earlier task whose `trace` is `task.trace.parent`; if + * `task.trace.parent` is the trace root itself, the event has no parent event + * (it is a direct child of the root). + * + * `logs` (if given) are interleaved as synthetic events: each log's parent is + * the task event whose trace matches the log's current trace at emission + * time (or the nearest ancestor task event), and its time is inherited from + * that parent. Within a single parent task, logs are kept in emission order + * and inserted directly after the parent event. + */ +export function buildHistoryFromTasks( + tasks: readonly ScheduledTaskLike[], + startTime: number, + logs: readonly LogEntryLike[] = [], +): ExecutionHistory { + const rootByTrace = new Map(); + const roots: ExecutionRoot[] = []; + const eventByTrace = new Map(); + const taskEvents: ExecutionEvent[] = []; + + for (const task of tasks) { + const trace = task.trace; + if (!trace) { continue; } + + let root = rootByTrace.get(trace.root); + if (!root) { + root = { label: trace.root.label }; + rootByTrace.set(trace.root, root); + roots.push(root); + } + + // Find the parent event by walking up the trace chain until we hit + // either a trace whose event we know, or the trace root. + let parentEvent: ExecutionEvent | undefined; + for (let p = trace.parent; p; p = p.parent) { + const e = eventByTrace.get(p); + if (e) { parentEvent = e; break; } + } + + const event: ExecutionEvent = { + time: task.time - startTime, + label: `${task.source}`, + root, + parent: parentEvent, + detail: extractCallerFrame(task.source.stackTrace), + }; + eventByTrace.set(trace, event); + taskEvents.push(event); + } + + // Group log entries by their parent task event, preserving emission + // order within each group. A log without an enclosing task event is + // dropped (e.g. logs emitted at root before any task ran). + const logsByParent = new Map(); + for (const entry of logs) { + let parentEvent: ExecutionEvent | undefined; + for (let p: TraceLike | undefined = entry.trace; p; p = p.parent) { + const e = eventByTrace.get(p); + if (e) { parentEvent = e; break; } + } + if (!parentEvent) { continue; } + + const logEvent: ExecutionEvent = { + time: parentEvent.time, + label: `log: ${entry.message}`, + root: parentEvent.root, + parent: parentEvent, + }; + const bucket = logsByParent.get(parentEvent); + if (bucket) { bucket.push(logEvent); } + else { logsByParent.set(parentEvent, [logEvent]); } + } + + // Interleave: each task event followed by its logs in emission order. + const events: ExecutionEvent[] = []; + for (const e of taskEvents) { + events.push(e); + const ls = logsByParent.get(e); + if (ls) { events.push(...ls); } + } + + return { roots, events }; +} + +/** + * Extract the first stack frame that is not from the scheduler/tracing + * infrastructure. Returns `undefined` when no useful frame is found. + */ +const _skipFramePatterns = [ + /timeTravelScheduler|traceableTimeApi/, + /RunOnceScheduler\.schedule/, + /scheduleAtNextAnimationFrame/, + /TimeoutTimer\.cancelAndSet/, + /TimeoutTimer\.setIfNotSet/, + /timeoutDeferred/, + /createTimeout/, +]; + +function extractCallerFrame(stackTrace: string | undefined): string | undefined { + if (!stackTrace) { return undefined; } + for (const line of stackTrace.split('\n')) { + const trimmed = line.trim(); + if (!trimmed.startsWith('at ')) { continue; } + if (_skipFramePatterns.some(p => p.test(trimmed))) { continue; } + return trimmed.slice(3); + } + return undefined; +} + +// ----------------------------------------------------------------------------- +// Renderer: swimlane (one column per root) +// ----------------------------------------------------------------------------- + +/** + * Render `history` as a swimlane diagram: one column per root, events in the + * column of their root, parent→child shown via `├─`/`└─` indentation, active + * ancestors shown via `│` continuation lines. + * + * Example: + * ``` + * A B + * +0ms ├─ setTimeout + * +10ms │ ├─ setTimeout + * +16ms ├─ rAF │ + * +50ms └─ setTimeout + * ``` + */ +export function renderSwimlanes(history: ExecutionHistory): string { + const { roots, events } = history; + if (events.length === 0) { return '(empty history)'; } + if (roots.length === 0) { + return events.map(e => `[+${e.time}ms] ${e.label}`).join('\n'); + } + + const n = events.length; + + // Parent index per event (-1 = direct child of root). + const parentOf = new Array(n).fill(-1); + const childrenOf: number[][] = Array.from({ length: n }, () => []); + const indexOfEvent = new Map(); + for (let i = 0; i < n; i++) { indexOfEvent.set(events[i], i); } + for (let i = 0; i < n; i++) { + const p = events[i].parent; + if (p) { + const pi = indexOfEvent.get(p); + if (pi !== undefined) { + parentOf[i] = pi; + childrenOf[pi].push(i); + } + } + } + + // Is this event the last child of its parent event? + const isLastChild = new Array(n).fill(false); + for (let i = 0; i < n; i++) { + const p = parentOf[i]; + if (p >= 0 && childrenOf[p][childrenOf[p].length - 1] === i) { isLastChild[i] = true; } + } + + // Slot = visual column index for indentation. By default every child + // gets its own column (slot = parent.slot + 1) so pure last-child chains + // still show their depth structure. Once we pass the depth threshold, + // last-children collapse into their parent's slot to keep deeply nested + // traces from walking off the screen. + const COLLAPSE_DEPTH_THRESHOLD = 6; + const depthOf = new Array(n).fill(0); + const slotOf = new Array(n).fill(0); + for (let i = 0; i < n; i++) { + const p = parentOf[i]; + if (p >= 0) { + depthOf[i] = depthOf[p] + 1; + const collapse = isLastChild[i] && depthOf[i] >= COLLAPSE_DEPTH_THRESHOLD; + slotOf[i] = slotOf[p] + (collapse ? 0 : 1); + } + } + + // Column width per root: indentation uses slots (last-children collapse + // into their parent's slot), so width must be slot-based to avoid + // reserving empty space for degenerate last-child chains. + const widthOf = new Map(); + for (const r of roots) { widthOf.set(r, r.label.length); } + for (let i = 0; i < n; i++) { + const w = slotOf[i] * 3 + 3 + events[i].label.length; + const cur = widthOf.get(events[i].root) ?? 0; + if (w > cur) { widthOf.set(events[i].root, w); } + } + + // Compute time column width based on max time (rounded). + const maxTime = n > 0 ? Math.max(...events.map(e => Math.round(e.time))) : 0; + const timeColWidth = `+${maxTime}ms`.length; + + const lines: string[] = []; + + // Header: root labels centered in their columns. + const header: string[] = []; + for (const r of roots) { + const w = widthOf.get(r)!; + header.push(r.label.padStart(Math.ceil((w + r.label.length) / 2)).padEnd(w)); + } + lines.push(`${' '.repeat(timeColWidth)} ${header.join(' ')}`.trimEnd()); + + // Compute lastChild index for each event (for drawing continuation lines). + const lastChildOf = new Array(n).fill(-1); + for (let i = 0; i < n; i++) { + const kids = childrenOf[i]; + if (kids.length > 0) { lastChildOf[i] = kids[kids.length - 1]; } + } + + // Per-root: set of "active ancestor" event indices (events with children + // whose last child has not yet been rendered, i.e. lastChildOf[a] > i). + const laneStacks = new Map>(); + for (const r of roots) { laneStacks.set(r, new Set()); } + + for (let i = 0; i < n; i++) { + const event = events[i]; + const timeStr = `+${Math.round(event.time)}ms`.padStart(timeColWidth); + + const parts: string[] = []; + for (const r of roots) { + const w = widthOf.get(r)!; + const stack = laneStacks.get(r)!; + + if (r === event.root) { + // Event line: slot-based indentation, then `├─`/`└─` + label. + // For each slot s in 0..(slot-1), show `│ ` if an ancestor + // at slot s is still active (lastChild > current), else ` `. + const slot = slotOf[i]; + const indent: string[] = []; + for (let s = 0; s < slot; s++) { + let hasActive = false; + for (const a of stack) { + if (slotOf[a] === s && lastChildOf[a] > i) { hasActive = true; break; } + } + indent.push(hasActive ? '│ ' : ' '); + } + const prefix = isLastChild[i] ? '└─ ' : '├─ '; + parts.push(`${indent.join('')}${prefix}${event.label}`.padEnd(w)); + } else { + // Cross-lane continuation. Draw `│` at each slot occupied by + // an active ancestor (lastChild > i). Also show a `|` placeholder + // at the slot of the next upcoming event if it's a non-last child. + const activeSlots: number[] = []; + for (const a of stack) { + if (lastChildOf[a] > i) { activeSlots.push(slotOf[a]); } + } + const maxSlot = Math.max(...activeSlots, -1); + const chars: string[] = new Array(Math.max(maxSlot + 1, 0)).fill(' '); + for (const s of activeSlots) { chars[s] = '│ '; } + + // Find the next event in root r strictly after i. + let nextJ = -1; + for (let j = i + 1; j < n; j++) { + if (events[j].root === r) { nextJ = j; break; } + } + if (nextJ >= 0 && parentOf[nextJ] >= 0) { + const s = slotOf[nextJ]; + // Reserve slot if next event will open a new branch (├─). + if (!isLastChild[nextJ]) { + while (chars.length <= s) { chars.push(' '); } + if (chars[s] === ' ') { chars[s] = '| '; } + } + } + + // Trim trailing empty cells. + while (chars.length > 0 && chars[chars.length - 1] === ' ') { chars.pop(); } + parts.push(chars.join('').padEnd(w)); + } + } + + lines.push(`${timeStr} ${parts.join(' ')}`.trimEnd()); + + // Stack maintenance: push this event if it has children, then pop + // any ancestors whose last child was just rendered (propagating up). + const stack = laneStacks.get(event.root)!; + if (childrenOf[i].length > 0) { stack.add(i); } + let cur = i; + while (isLastChild[cur]) { + const p = parentOf[cur]; + if (p < 0) { break; } + stack.delete(p); + cur = p; + } + } + + return lines.join('\n'); +} + +// ----------------------------------------------------------------------------- +// Renderer: interleaved lane graph (git-log style) +// ----------------------------------------------------------------------------- + +/** + * Render `history` as an interleaved-lane "git log" style graph. Each parent + * event gets a column; columns are laid out left-to-right in event order. + * Trace roots with at least one direct child become synthetic `+label` rows + * inserted before their first child. + * + * Glyphs: + * `╷` lane origin (this node is a parent) + * `│` lane passes through + * `├─` child connects; lane continues + * `└─` last child connects; lane closes + * `┼─` horizontal connector crosses an active lane + * `──` horizontal connector crosses an empty column + */ +export function renderLaneGraph(history: ExecutionHistory): string { + const { events } = history; + if (events.length === 0) { return ''; } + + interface Node { + readonly label: string; + readonly parent: Node | undefined; + readonly isSynthetic: boolean; + } + + // Insert synthetic root nodes before their first child. + const nodes: Node[] = []; + const syntheticForRoot = new Map(); + const nodeByEvent = new Map(); + + // Which roots have at least one direct child event? + const rootsWithChildren = new Set(); + for (const e of events) { if (!e.parent) { rootsWithChildren.add(e.root); } } + + for (const e of events) { + if (rootsWithChildren.has(e.root) && !syntheticForRoot.has(e.root)) { + const syn: Node = { label: `+${e.root.label}`, parent: undefined, isSynthetic: true }; + syntheticForRoot.set(e.root, syn); + nodes.push(syn); + } + const timeStr = `+${e.time}ms`.padStart(7); + const parent = e.parent ? nodeByEvent.get(e.parent)! : syntheticForRoot.get(e.root); + const node: Node = { label: `[${timeStr}] ${e.label}`, parent, isSynthetic: false }; + nodeByEvent.set(e, node); + nodes.push(node); + } + + const n = nodes.length; + const parentOf = new Array(n).fill(-1); + const childrenOf: number[][] = Array.from({ length: n }, () => []); + const indexOfNode = new Map(); + for (let i = 0; i < n; i++) { indexOfNode.set(nodes[i], i); } + for (let i = 0; i < n; i++) { + const p = nodes[i].parent; + if (p) { + const pi = indexOfNode.get(p); + if (pi !== undefined) { parentOf[i] = pi; childrenOf[pi].push(i); } + } + } + + // Assign columns: every node with children gets its own column. + const colOf = new Array(n).fill(-1); + let totalCols = 0; + for (let i = 0; i < n; i++) { + if (childrenOf[i].length > 0) { colOf[i] = totalCols++; } + } + + if (totalCols === 0) { + return events.map(e => `[+${`${e.time}ms`.padStart(5)}] ${e.label}`).join('\n'); + } + + const active = new Array(totalCols).fill(-1); + const lines: string[] = []; + + for (let i = 0; i < n; i++) { + const node = nodes[i]; + const pIdx = parentOf[i]; + const connectCol = pIdx >= 0 ? colOf[pIdx] : -1; + const last = pIdx >= 0 && childrenOf[pIdx][childrenOf[pIdx].length - 1] === i; + const opensCol = childrenOf[i].length > 0 ? colOf[i] : -1; + const horizEnd = pIdx >= 0 ? (opensCol >= 0 ? opensCol : totalCols) : -1; + + const chars: string[] = []; + for (let c = 0; c < totalCols; c++) { + const isActive = active[c] >= 0; + const isConnect = c === connectCol; + const isOpen = c === opensCol && !isConnect; + const inHoriz = connectCol >= 0 && c > connectCol && c < horizEnd; + + let g: string, s: string; + if (isConnect) { + g = last ? '└' : '├'; + s = '─'; + } else if (isOpen && node.isSynthetic) { + g = '+'; + s = node.label.slice(1, 2) || '?'; + } else if (isOpen && connectCol >= 0) { + g = '╷'; s = '─'; + } else if (isOpen) { + g = '╷'; s = ' '; + } else if (inHoriz && isActive) { + g = '┼'; s = '─'; + } else if (inHoriz) { + g = '─'; s = '─'; + } else if (isActive) { + g = '│'; s = ' '; + } else { + g = ' '; s = ' '; + } + chars.push(g, s); + } + + if (last) { active[colOf[pIdx]] = -1; } + if (opensCol >= 0) { active[opensCol] = i; } + + if (node.isSynthetic) { + lines.push(chars.join('').trimEnd()); + } else { + lines.push(`${chars.join('')}${node.label}`); + } + } + + return lines.join('\n'); +} diff --git a/src/vs/base/test/common/timeTravelScheduler.ts b/src/vs/base/test/common/timeTravelScheduler.ts index f927a82403f..c0ccae014be 100644 --- a/src/vs/base/test/common/timeTravelScheduler.ts +++ b/src/vs/base/test/common/timeTravelScheduler.ts @@ -4,9 +4,11 @@ *--------------------------------------------------------------------------------------------*/ import { compareBy, numberComparator, tieBreakComparators } from '../../common/arrays.js'; -import { Emitter, Event } from '../../common/event.js'; -import { Disposable, IDisposable } from '../../common/lifecycle.js'; +import { CancellationToken, CancellationTokenSource } from '../../common/cancellation.js'; +import { Emitter } from '../../common/event.js'; +import { Disposable, DisposableStore, IDisposable } from '../../common/lifecycle.js'; import { setTimeout0, setTimeout0IsFaster } from '../../common/platform.js'; +import { ROOT_TRACE, Trace, TraceContext } from './traceableTimeApi.js'; export type TimeOffset = number; @@ -19,6 +21,12 @@ export interface ScheduledTask { readonly time: TimeOffset; readonly source: ScheduledTaskSource; readonly useRealAnimationFrame?: boolean; + /** + * Causal trace attached at schedule time. Used for attribution in + * `toString()` and to re-install the trace when the task runs so that + * the task body (and its microtask drain) observes it. + */ + readonly trace?: Trace; run(): void; } @@ -38,6 +46,7 @@ export interface TimeApi { requestAnimationFrame?: ((callback: (time: number) => void) => number); cancelAnimationFrame?: ((id: number) => void); Date: DateConstructor; + originalFunctions?: TimeApi; } interface ExtendedScheduledTask extends ScheduledTask { @@ -98,122 +107,457 @@ export class TimeTravelScheduler implements Scheduler { } installGlobally(options?: CreateVirtualTimeApiOptions): IDisposable { - return overwriteGlobalTimeApi(createVirtualTimeApi(this, options)); + return pushGlobalTimeApi(createVirtualTimeApi(this, options)); } } +/** + * Termination policy of a single {@link AsyncSchedulerProcessor.run} call. + */ +export interface RunOptions { + /** + * If set, the run resolves once the token is cancelled AND the virtual queue + * has been drained. Tasks scheduled before cancellation are still processed. + * If unset, the run resolves as soon as the virtual queue is empty. + */ + readonly token?: CancellationToken; + /** + * If set, the run resolves once virtual time has reached this absolute + * timestamp, OR there is no scheduled task with `time <= virtualDeadline` + * (because then virtual time can never reach the deadline by itself). + */ + readonly virtualDeadline?: TimeOffset; + /** + * Maximum number of virtual tasks this run will tolerate executing while + * its termination predicate is not yet satisfied. Exceeding this rejects + * the run with a debug-friendly overflow error. + * + * Counted from the moment the run was started, not from processor creation. + */ + readonly maxTasks?: number; + /** + * Maximum causal chain depth (via {@link Trace.depth}) the run will + * tolerate. If a task is about to execute whose trace depth exceeds this + * limit, the run is rejected. Useful for catching runaway self-rescheduling + * (a timer that keeps scheduling its own successor indefinitely). + */ + readonly maxTaskDepth?: number; +} + +type RunStatus = 'continue' | 'done' | { readonly error: Error }; + +/** + * Internal record of a single {@link AsyncSchedulerProcessor.run} call. + * + * A {@link Run} is purely declarative: its termination predicate + * ({@link evaluate}) is a pure function over the processor's observable state + * (`scheduler.now`, `executedTotal`, the next task time, the token state). + * The processor never mutates a run; it only inspects it and, when done, + * resolves or rejects its {@link promise}. + */ +class Run { + + private static _idCounter = 0; + public readonly id = ++Run._idCounter; + + public readonly promise: Promise; + private _resolve!: () => void; + private _reject!: (e: Error) => void; + private _settled = false; + public get settled(): boolean { return this._settled; } + + constructor( + public readonly options: RunOptions, + public readonly tasksExecutedAtStart: number, + public readonly effectiveMaxTasks: number, + ) { + this.promise = new Promise((res, rej) => { + this._resolve = res; + this._reject = rej; + }); + } + + settle(error?: Error): void { + if (this._settled) { return; } + this._settled = true; + if (error) { this._reject(error); } else { this._resolve(); } + } + + evaluate(scheduler: TimeTravelScheduler, executedTotal: number, peekNextTime: TimeOffset | undefined, makeOverflowError: () => Error): RunStatus { + const localExecuted = executedTotal - this.tasksExecutedAtStart; + if (localExecuted >= this.effectiveMaxTasks && scheduler.hasScheduledTasks) { + return { error: makeOverflowError() }; + } + + if (this.options.virtualDeadline !== undefined) { + if (scheduler.now >= this.options.virtualDeadline) { return 'done'; } + // Virtual time can only advance by executing tasks. If no scheduled + // task can advance time up to the deadline, the run is effectively + // done (otherwise the loop would idle-wait forever). + if (peekNextTime === undefined || peekNextTime > this.options.virtualDeadline) { return 'done'; } + } + + if (this.options.token === undefined) { + return scheduler.hasScheduledTasks ? 'continue' : 'done'; + } + + if (this.options.token.isCancellationRequested && !scheduler.hasScheduledTasks) { return 'done'; } + return 'continue'; + } + + describe(executedTotal: number, startTime: TimeOffset): string { + const parts: string[] = [`#${this.id}`]; + if (this.options.token) { + parts.push(this.options.token.isCancellationRequested ? 'token=cancelled' : 'token=pending'); + } + if (this.options.virtualDeadline !== undefined) { + const delta = this.options.virtualDeadline - startTime; + const sign = delta < 0 ? '-' : '+'; + parts.push(`virtualDeadline=${sign}${Math.abs(delta)}ms`); + } + const localExecuted = executedTotal - this.tasksExecutedAtStart; + parts.push(`executed=${localExecuted}/${this.effectiveMaxTasks}`); + return parts.join(' '); + } +} + +/** + * Drives a {@link TimeTravelScheduler} from the real microtask/macrotask queue, + * yielding back to real time between virtual tasks so that promise callbacks + * can run and (re)schedule virtual tasks before the next one is executed. + * + * # Invariants + * + * 1. **Single physical loop.** At any moment at most one async loop iterates + * the virtual queue. Concurrent {@link run} calls compose by registering + * additional {@link Run}s on the same loop. + * + * 2. **Yield-then-execute.** Each loop iteration yields to real time before + * executing the next virtual task. No two virtual tasks run back-to-back + * without a yield. Termination is re-evaluated after each yield. + * + * 3. **Termination is per-run and pure.** Each run carries its own termination + * options ({@link RunOptions}); deadlines, tokens and maxTasks are never + * stored as mutable processor state. This is what makes parallel runs with + * different deadlines compose cleanly. + * + * 4. **Loop respects the strictest deadline.** The loop never advances virtual + * time past `min(virtualDeadline of all active runs)`. Past-deadline runs + * are settled before the loop attempts the next yield. + * + * 5. **Idle waits are explicit and breakable.** When the queue is empty (or + * the next task is past every active deadline) the loop awaits a single + * composite signal: a new task being scheduled, a run being added, or a + * token being cancelled. It never busy-loops. + * + * 6. **Errors propagate via promise rejection.** A throwing virtual task or a + * {@link RunOptions.maxTasks} overflow rejects the relevant run(s). No + * sticky `_lastError` flag is left for the next caller. + * + * 7. **Disposal settles all runs.** {@link dispose} rejects every active run + * with a disposal error and lets the loop drain naturally. + */ export class AsyncSchedulerProcessor extends Disposable { - private isProcessing = false; - private readonly _history = new Array(); + + private readonly _runs = new Map(); + private readonly _history: ScheduledTask[] = []; + private _executedTotal = 0; + + private _loopRunning = false; + private _wakeup: (() => void) | undefined; + + private readonly _defaultMaxTasks: number; + private readonly _useSetImmediate: boolean; + private readonly _realTimeApi: TimeApi; + private readonly _startTime: TimeOffset; + public get history(): readonly ScheduledTask[] { return this._history; } - private readonly maxTaskCount: number; - private readonly useSetImmediate: boolean; - private readonly _realTimeApi: TimeApi; - - private readonly queueEmptyEmitter = new Emitter(); - public readonly onTaskQueueEmpty = this.queueEmptyEmitter.event; - - private lastError: Error | undefined; - private _virtualDeadline = Number.MAX_SAFE_INTEGER; - - constructor(private readonly scheduler: TimeTravelScheduler, options?: { useSetImmediate?: boolean; maxTaskCount?: number; realTimeApi?: TimeApi }) { + constructor( + private readonly scheduler: TimeTravelScheduler, + options?: { useSetImmediate?: boolean; maxTaskCount?: number; realTimeApi?: TimeApi } + ) { super(); - - this.maxTaskCount = options && options.maxTaskCount ? options.maxTaskCount : 100; - this.useSetImmediate = options && options.useSetImmediate ? options.useSetImmediate : false; + this._defaultMaxTasks = options?.maxTaskCount ?? 100; + this._useSetImmediate = options?.useSetImmediate ?? false; this._realTimeApi = options?.realTimeApi ?? originalGlobalValues; + this._startTime = scheduler.now; - this._register(scheduler.onTaskScheduled(() => { - if (this.isProcessing) { - return; - } else { - this.isProcessing = true; - this._schedule(); - } - })); + this._register({ dispose: () => this._disposeAllRuns() }); } - private _schedule() { - // This allows promises created by a previous task to settle and schedule tasks before the next task is run. - // Tasks scheduled in those promises might have to run before the current next task. - Promise.resolve().then(() => { - // When the next task requires a real animation frame (e.g. virtual rAF), - // use the real browser rAF so the browser reflows before the callback runs. - // This ensures DOM measurements like offsetHeight return accurate values. - const nextTask = this.scheduler.peekNext(); - if (nextTask?.useRealAnimationFrame && this._realTimeApi.requestAnimationFrame) { - this._realTimeApi.requestAnimationFrame(() => this._process()); - } else if (this.useSetImmediate && this._realTimeApi.setImmediate) { - this._realTimeApi.setImmediate(() => this._process()); - } else if (setTimeout0IsFaster) { - setTimeout0(() => this._process()); - } else { - this._realTimeApi.setTimeout(() => this._process()); + /** + * Start a run with the given termination policy. + * + * - With no options: resolves when the virtual queue is empty. + * - With `token`: resolves when the token is cancelled AND the queue is + * drained. Tasks scheduled before cancellation are still processed. + * - With `virtualDeadline`: resolves when virtual time reaches the deadline, + * or when no scheduled task remains within it. + * - With `maxTasks`: rejects if the run executes more than that many virtual + * tasks before its other termination conditions are satisfied. + * + * Multiple parallel runs share the same processing loop; each resolves + * independently when its own predicate fires. + */ + run(options: RunOptions = {}): Promise { + return this._startRun(options); + } + + private _startRun(options: RunOptions): Promise { + const run = new Run(options, this._executedTotal, options.maxTasks ?? this._defaultMaxTasks); + const cleanup = new DisposableStore(); + if (options.token) { + cleanup.add(options.token.onCancellationRequested(() => this._wake())); + } + this._runs.set(run, cleanup); + this._wake(); + void this._ensureLoopRunning(); + return run.promise; + } + + private _settleRun(run: Run, error?: Error): void { + const cleanup = this._runs.get(run); + if (!cleanup) { return; } + this._runs.delete(run); + cleanup.dispose(); + run.settle(error); + } + + private _disposeAllRuns(): void { + const err = new Error('AsyncSchedulerProcessor disposed'); + for (const run of [...this._runs.keys()]) { + this._settleRun(run, err); + } + this._wake(); + } + + private _wake(): void { + const w = this._wakeup; + this._wakeup = undefined; + w?.(); + } + + private async _ensureLoopRunning(): Promise { + if (this._loopRunning) { return; } + this._loopRunning = true; + try { + await this._loop(); + } finally { + this._loopRunning = false; + } + } + + private async _loop(): Promise { + while (true) { + this._settleFinishedRuns(); + if (this._runs.size === 0) { return; } + + const next = this.scheduler.peekNext(); + const minDeadline = this._minDeadline(); + + if (!next || next.time > minDeadline) { + // Nothing actionable. Wait for a new task to be scheduled, a + // token to be cancelled, a new run to be added, or disposal. + await this._waitForChange(); + continue; } + + // Invariant 2: yield to real time before each virtual execution. + await this._yieldToReal(next); + + // Re-check after yielding: anything could have changed. + this._settleFinishedRuns(); + if (this._runs.size === 0) { return; } + + const stillNext = this.scheduler.peekNext(); + if (!stillNext || stillNext.time > this._minDeadline()) { continue; } + + // Check per-run maxTaskDepth: if this task's causal depth exceeds + // any active run's limit, reject that run before executing. + const taskDepth = stillNext.trace?.depth ?? 0; + let overflowed = false; + for (const run of [...this._runs.keys()]) { + const limit = run.options.maxTaskDepth; + if (limit !== undefined && taskDepth > limit) { + this._settleRun(run, this._buildDepthOverflowError(run, taskDepth)); + overflowed = true; + } + } + if (overflowed) { continue; } + + try { + // Execute the task under its causal trace so that its body + // and subsequent microtask drain observe it. `runAsHandler` + // keeps the trace in place across the microtask drain by + // scheduling a seq-guarded reset on the next real-time tick. + TraceContext.instance.runAsHandler(stillNext.trace ?? ROOT_TRACE, () => { + const executed = this.scheduler.runNext(); + if (executed) { + this._history.push(executed); + this._executedTotal++; + } + }, this._realTimeApi); + } catch (e) { + const err = e instanceof Error ? e : new Error(String(e)); + // We can't tell which run "owned" the throwing task. Reject all + // active runs so the failure is observed exactly once per caller. + for (const run of [...this._runs.keys()]) { + this._settleRun(run, err); + } + } + } + } + + private _settleFinishedRuns(): void { + const peekNextTime = this.scheduler.peekNext()?.time; + for (const run of [...this._runs.keys()]) { + if (run.settled) { continue; } + const status = run.evaluate(this.scheduler, this._executedTotal, peekNextTime, () => this._buildOverflowError(run)); + if (status === 'done') { + this._settleRun(run); + } else if (typeof status === 'object') { + this._settleRun(run, status.error); + } + } + } + + private _minDeadline(): TimeOffset { + let m = Number.MAX_SAFE_INTEGER; + for (const run of this._runs.keys()) { + if (run.options.virtualDeadline !== undefined && run.options.virtualDeadline < m) { + m = run.options.virtualDeadline; + } + } + return m; + } + + private _waitForChange(): Promise { + return new Promise(resolve => { + const store = new DisposableStore(); + const fire = () => { + if (this._wakeup === fire) { this._wakeup = undefined; } + store.dispose(); + resolve(); + }; + this._wakeup = fire; + store.add(this.scheduler.onTaskScheduled(fire)); }); } - private _process() { - let executedTask: ScheduledTask | undefined; - try { - executedTask = this.scheduler.runNext(); - } catch (e) { - console.error(`[TimeTravelScheduler] Task threw:`, e); - } - if (executedTask) { - this._history.push(executedTask); - - if (this.history.length >= this.maxTaskCount && this.scheduler.hasScheduledTasks) { - const lastTasks = this._history.slice(Math.max(0, this.history.length - 10)).map(h => `${h.source.toString()}: ${h.source.stackTrace}`); - this.lastError = new Error(`Queue did not get empty after processing ${this.history.length} items. These are the last ${lastTasks.length} scheduled tasks:\n${lastTasks.join('\n\n\n')}`); - this.isProcessing = false; - this.queueEmptyEmitter.fire(); - return; - } - - if (this.scheduler.now >= this._virtualDeadline && this.scheduler.hasScheduledTasks) { - this.isProcessing = false; - this.queueEmptyEmitter.fire(); - return; - } - } - - if (this.scheduler.hasScheduledTasks) { - this._schedule(); - } else { - this.isProcessing = false; - this.queueEmptyEmitter.fire(); - } - } - - waitForEmptyQueue(): Promise { - if (this.lastError) { - const error = this.lastError; - this.lastError = undefined; - throw error; - } - if (!this.isProcessing) { - return Promise.resolve(); - } else { - return Event.toPromise(this.onTaskQueueEmpty).then(() => { - if (this.lastError) { - const error = this.lastError; - this.lastError = undefined; - throw error; + private _yieldToReal(next: ScheduledTask): Promise { + return new Promise(resolve => { + // Drain microtasks first so promises chained to the previous task + // can settle and schedule virtual tasks before the next runs. + Promise.resolve().then(() => { + if (next.useRealAnimationFrame && this._realTimeApi.requestAnimationFrame) { + this._realTimeApi.requestAnimationFrame(() => resolve()); + } else if (this._useSetImmediate && this._realTimeApi.setImmediate) { + this._realTimeApi.setImmediate(() => resolve()); + } else if (setTimeout0IsFaster) { + setTimeout0(() => resolve()); + } else { + this._realTimeApi.setTimeout(() => resolve()); } }); - } + }); } - runForVirtualTimeMs(virtualTimeMs: number): Promise { - this._virtualDeadline = this.scheduler.now + virtualTimeMs; - return this.waitForEmptyQueue().finally(() => { - this._virtualDeadline = Number.MAX_SAFE_INTEGER; - }); + private _buildOverflowError(run: Run): Error { + const localExecuted = this._executedTotal - run.tasksExecutedAtStart; + const limit = run.effectiveMaxTasks; + return new Error( + `[AsyncSchedulerProcessor] Run #${run.id} exceeded maxTasks (${limit}) — ` + + `executed ${localExecuted} virtual task(s) and the queue is still not empty.\n\n` + + this.toString() + ); + } + + private _buildDepthOverflowError(run: Run, taskDepth: number): Error { + const limit = run.options.maxTaskDepth!; + return new Error( + `[AsyncSchedulerProcessor] Run #${run.id} exceeded maxTaskDepth (${limit}) — ` + + `next task has causal depth ${taskDepth}. This usually indicates ` + + `a runaway self-rescheduling timer.\n\n` + + this.toString() + ); + } + + /** + * A debug-friendly snapshot of the processor: virtual time, active runs, + * recent history (with stack traces) and currently queued tasks. + */ + override toString(): string { + const queued = this.scheduler.getScheduledTasks(); + const lines: string[] = []; + const fmt = (task: ScheduledTask, indent: string) => formatScheduledTask(task, indent, this._startTime); + + lines.push( + `AsyncSchedulerProcessor { ` + + `now=+${this.scheduler.now - this._startTime}ms, ` + + `executed=${this._executedTotal}, ` + + `queued=${queued.length}, ` + + `runs=${this._runs.size}, ` + + `loopRunning=${this._loopRunning} }` + ); + + if (this._runs.size > 0) { + lines.push(''); + lines.push('Active runs:'); + for (const run of this._runs.keys()) { + lines.push(` ${run.describe(this._executedTotal, this._startTime)}`); + } + } + + const HISTORY_LIMIT = 10; + if (this._history.length > 0) { + const recent = this._history.slice(-HISTORY_LIMIT); + lines.push(''); + const omitted = this._history.length - recent.length; + lines.push(`History (${recent.length}${omitted > 0 ? ` of ${this._history.length}` : ''}):`); + for (const t of recent) { + lines.push(fmt(t, ' ')); + } + } + + if (queued.length > 0) { + const QUEUE_LIMIT = 20; + const shown = queued.slice(0, QUEUE_LIMIT); + lines.push(''); + lines.push(`Queued (${queued.length}):`); + for (const t of shown) { + lines.push(fmt(t, ' ')); + } + if (queued.length > shown.length) { + lines.push(` ... and ${queued.length - shown.length} more`); + } + } + + return lines.join('\n'); } } +function formatScheduledTask(task: ScheduledTask, indent: string, startTime: TimeOffset): string { + const delta = task.time - startTime; + const sign = delta < 0 ? '-' : '+'; + const time = `${sign}${Math.abs(delta)}ms`.padStart(8); + const head = `${indent}[${time}] ${task.source.toString()}`; + const lines: string[] = [head]; + if (task.trace) { + lines.push(`${indent} trace: ${task.trace.describe()}`); + } + const stack = task.source.stackTrace; + if (stack) { + const stackLines = stack.split('\n').map(l => l.trim()).filter(l => l.length > 0); + // Drop the leading "Error" line that `new Error().stack` produces, + // then keep a few useful frames. + const frames = (stackLines[0]?.startsWith('Error') ? stackLines.slice(1) : stackLines).slice(0, 5); + for (const f of frames) { + lines.push(`${indent} ${f}`); + } + } + return lines.join('\n'); +} export async function runWithFakedTimers(options: { startTime?: number; useFakeTimers?: boolean; useSetImmediate?: boolean; maxTaskCount?: number }, fn: () => Promise): Promise { const useFakeTimers = options.useFakeTimers === undefined ? true : options.useFakeTimers; @@ -225,6 +569,12 @@ export async function runWithFakedTimers(options: { startTime?: number; useFa const schedulerProcessor = new AsyncSchedulerProcessor(scheduler, { useSetImmediate: options.useSetImmediate, maxTaskCount: options.maxTaskCount }); const globalInstallDisposable = scheduler.installGlobally(); + // Start processing. With a token, run() keeps processing tasks until the + // token is cancelled and the queue is drained, so tasks scheduled during + // fn() are processed concurrently. + const cts = new CancellationTokenSource(); + const runPromise = schedulerProcessor.run({ token: cts.token }); + let didThrow = true; let result: T; try { @@ -233,13 +583,21 @@ export async function runWithFakedTimers(options: { startTime?: number; useFa } finally { globalInstallDisposable.dispose(); + // Signal that fn() is done: run() should drain the queue (for success) + // or stop immediately (for error) and then resolve. + // Since the global override is already disposed, no more tasks will be + // scheduled during the final drain. + cts.cancel(); + try { if (!didThrow) { - // We process the remaining scheduled tasks. - // The global override is no longer active, so during this, no more tasks will be scheduled. - await schedulerProcessor.waitForEmptyQueue(); + await runPromise; + } else { + // Avoid an unhandled rejection when disposal below rejects the run. + runPromise.catch(() => { /* swallowed: fn() already failed */ }); } } finally { + cts.dispose(); schedulerProcessor.dispose(); } } @@ -258,6 +616,17 @@ export function captureGlobalTimeApi(): TimeApi { requestAnimationFrame: globalThis.requestAnimationFrame?.bind(globalThis), cancelAnimationFrame: globalThis.cancelAnimationFrame?.bind(globalThis), Date: globalThis.Date, + originalFunctions: { + setTimeout: globalThis.setTimeout, + clearTimeout: globalThis.clearTimeout, + setInterval: globalThis.setInterval, + clearInterval: globalThis.clearInterval, + setImmediate: globalThis.setImmediate, + clearImmediate: globalThis.clearImmediate, + requestAnimationFrame: globalThis.requestAnimationFrame, + cancelAnimationFrame: globalThis.cancelAnimationFrame, + Date: globalThis.Date, + }, }; } @@ -276,13 +645,16 @@ export function createVirtualTimeApi(scheduler: Scheduler, options?: CreateVirtu if (typeof handler === 'string') { throw new Error('String handler args should not be used and are not supported'); } + const stackTrace = new Error().stack; + const trace = TraceContext.instance.currentTrace().child(`setTimeout(${timeout}ms)`, stackTrace); return scheduler.schedule({ time: scheduler.now + timeout, run: () => { handler(); }, source: { toString() { return 'setTimeout'; }, - stackTrace: new Error().stack, - } + stackTrace, + }, + trace, }); } @@ -299,6 +671,7 @@ export function createVirtualTimeApi(scheduler: Scheduler, options?: CreateVirtu const validatedHandler = handler; let iterCount = 0; const stackTrace = new Error().stack; + const baseTrace = TraceContext.instance.currentTrace().child(`setInterval(${interval}ms)`, stackTrace); let disposed = false; let lastDisposable: IDisposable; @@ -316,7 +689,8 @@ export function createVirtualTimeApi(scheduler: Scheduler, options?: CreateVirtu source: { toString() { return `setInterval (iteration ${curIter})`; }, stackTrace, - } + }, + trace: baseTrace.child(`tick #${curIter}`), }); } schedule(); @@ -370,12 +744,21 @@ export function createVirtualTimeApi(scheduler: Scheduler, options?: CreateVirtu }; /* eslint-enable local/code-no-any-casts */ + // Expose the real setTimeout as `originalFn` on the virtual one. The component-explorer + // host's polling loop reads `globalThis.setTimeout.originalFn` to escape virtual time + // when waiting for renders to settle. Without this, the host's poll re-arms inside + // virtual time and triggers the AsyncSchedulerProcessor's depth-overflow guard. + // eslint-disable-next-line local/code-no-any-casts + (api.setTimeout as any).originalFn = originalGlobalValues.setTimeout; + if (options?.fakeRequestAnimationFrame) { let rafIdCounter = 0; const rafDisposables = new Map(); api.requestAnimationFrame = (callback: (time: number) => void) => { const id = ++rafIdCounter; + const stackTrace = new Error().stack; + const trace = TraceContext.instance.currentTrace().child('requestAnimationFrame', stackTrace); // Advance virtual time by 16ms (~60fps). The task is marked with // useRealAnimationFrame so the AsyncSchedulerProcessor uses a real // browser rAF to schedule its execution, ensuring the browser @@ -390,8 +773,9 @@ export function createVirtualTimeApi(scheduler: Scheduler, options?: CreateVirtu }, source: { toString() { return 'requestAnimationFrame'; }, - stackTrace: new Error().stack, - } + stackTrace, + }, + trace, }); rafDisposables.set(id, disposable); return id; @@ -409,7 +793,7 @@ export function createVirtualTimeApi(scheduler: Scheduler, options?: CreateVirtu return api; } -export function overwriteGlobalTimeApi(api: TimeApi): IDisposable { +export function pushGlobalTimeApi(api: TimeApi): IDisposable { const captured = captureGlobalTimeApi(); // eslint-disable-next-line local/code-no-any-casts @@ -431,7 +815,7 @@ export function overwriteGlobalTimeApi(api: TimeApi): IDisposable { return { dispose: () => { - Object.assign(globalThis, captured); + Object.assign(globalThis, captured.originalFunctions ?? captured); } }; } diff --git a/src/vs/base/test/common/traceableTimeApi.test.ts b/src/vs/base/test/common/traceableTimeApi.test.ts new file mode 100644 index 00000000000..1629b571c1c --- /dev/null +++ b/src/vs/base/test/common/traceableTimeApi.test.ts @@ -0,0 +1,330 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import assert from 'assert'; +import { ensureNoDisposablesAreLeakedInTestSuite } from './utils.js'; +import { + createTraceRoot, + Trace, + TraceContext, +} from './traceableTimeApi.js'; +import { AsyncSchedulerProcessor, captureGlobalTimeApi, createVirtualTimeApi, TimeTravelScheduler } from './timeTravelScheduler.js'; +import { buildHistoryFromTasks, renderSwimlanes } from './executionGraph.js'; +import { DisposableStore } from '../../common/lifecycle.js'; + +/** Stable serialisation of a trace for snapshot assertions. */ +function traceInfo(t: Trace): { labels: string[]; rootLabel: string; depth: number } { + const labels: string[] = []; + for (let c: Trace | undefined = t; c; c = c.parent) { labels.push(c.label); } + return { labels, rootLabel: t.root.label, depth: t.depth }; +} + +suite('traceableTimeApi', () => { + ensureNoDisposablesAreLeakedInTestSuite(); + + teardown(() => TraceContext.instance._resetForTesting()); + + test('Trace.describe builds causal chain from leaf to root', () => { + const root = createTraceRoot('fixture'); + const t1 = root.child('setTimeout(100ms)'); + const t2 = t1.child('await continuation'); + assert.deepStrictEqual(traceInfo(t2), { + labels: ['await continuation', 'setTimeout(100ms)', 'fixture'], + rootLabel: 'fixture', + depth: 2, + }); + }); + + test('runWithTrace installs and restores synchronously; supports nesting', () => { + const a = createTraceRoot('a'); + const b = createTraceRoot('b'); + const observations: string[] = []; + observations.push(TraceContext.instance.currentTrace().label); + TraceContext.instance.runWithTrace(a, () => { + observations.push(TraceContext.instance.currentTrace().label); + TraceContext.instance.runWithTrace(b, () => { + observations.push(TraceContext.instance.currentTrace().label); + }); + observations.push(TraceContext.instance.currentTrace().label); + }); + observations.push(TraceContext.instance.currentTrace().label); + assert.deepStrictEqual(observations, ['', 'a', 'b', 'a', '']); + }); + + test('runAsHandler throws on sync re-entry', () => { + const realTime = captureGlobalTimeApi(); + const a = createTraceRoot('a'); + const b = createTraceRoot('b'); + assert.throws( + () => TraceContext.instance.runAsHandler(a, () => TraceContext.instance.runAsHandler(b, () => { }, realTime), realTime), + /re-entrant runAsHandler/, + ); + }); + + test('runAsHandler leaks trace across awaited microtasks', async () => { + const realTime = captureGlobalTimeApi(); + const fixtureRoot = createTraceRoot('fixture'); + const observations: string[] = []; + + await TraceContext.instance.runAsHandler(fixtureRoot, async () => { + observations.push(TraceContext.instance.currentTrace().label); + await Promise.resolve(); + observations.push(TraceContext.instance.currentTrace().label); + await Promise.resolve().then(() => Promise.resolve()); + observations.push(TraceContext.instance.currentTrace().label); + }, realTime); + + assert.deepStrictEqual(observations, ['fixture', 'fixture', 'fixture']); + }); + + test('tracing time api tags setTimeout, fires callback under captured trace', async () => { + const realTime = captureGlobalTimeApi(); + const tracing = TraceContext.instance.createTracingTimeApi(realTime, realTime); + const root = createTraceRoot('root'); + + const { promise, resolve } = deferred(); + TraceContext.instance.runAsHandler(root, () => { + tracing.setTimeout(() => resolve(TraceContext.instance.currentTrace()), 0); + }, realTime); + + const observed = await promise; + assert.deepStrictEqual(traceInfo(observed), { + labels: ['setTimeout(0ms)', 'root'], + rootLabel: 'root', + depth: 1, + }); + }); + + test('tracing time api: nested setTimeout preserves full causal chain', async () => { + const realTime = captureGlobalTimeApi(); + const tracing = TraceContext.instance.createTracingTimeApi(realTime, realTime); + const root = createTraceRoot('root'); + + const { promise, resolve } = deferred(); + TraceContext.instance.runAsHandler(root, () => { + tracing.setTimeout(() => { + tracing.setTimeout(() => resolve(TraceContext.instance.currentTrace()), 0); + }, 0); + }, realTime); + + const observed = await promise; + assert.deepStrictEqual(traceInfo(observed), { + labels: ['setTimeout(0ms)', 'setTimeout(0ms)', 'root'], + rootLabel: 'root', + depth: 2, + }); + }); + + test('setInterval: each tick gets a fresh child trace', async () => { + const realTime = captureGlobalTimeApi(); + const tracing = TraceContext.instance.createTracingTimeApi(realTime, realTime); + const root = createTraceRoot('root'); + + const observed: Trace[] = []; + const { promise, resolve } = deferred(); + let id: unknown; + TraceContext.instance.runAsHandler(root, () => { + id = tracing.setInterval(() => { + observed.push(TraceContext.instance.currentTrace()); + if (observed.length === 3) { tracing.clearInterval(id); resolve(); } + }, 5); + }, realTime); + + await promise; + assert.deepStrictEqual(observed.map(t => traceInfo(t)), [ + { labels: ['tick #1', 'setInterval(5ms)', 'root'], rootLabel: 'root', depth: 2 }, + { labels: ['tick #2', 'setInterval(5ms)', 'root'], rootLabel: 'root', depth: 2 }, + { labels: ['tick #3', 'setInterval(5ms)', 'root'], rootLabel: 'root', depth: 2 }, + ]); + }); + + test('concurrent runAsHandler via setTimeout 0: traces do not leak across handlers', async () => { + const realTime = captureGlobalTimeApi(); + const tracing = TraceContext.instance.createTracingTimeApi(realTime, realTime); + const a = createTraceRoot('a'); + const b = createTraceRoot('b'); + + const { promise: doneA, resolve: resA } = deferred(); + const { promise: doneB, resolve: resB } = deferred(); + TraceContext.instance.runAsHandler(a, () => { + tracing.setTimeout(() => resA(TraceContext.instance.currentTrace()), 0); + }, realTime); + TraceContext.instance.runAsHandler(b, () => { + tracing.setTimeout(() => resB(TraceContext.instance.currentTrace()), 0); + }, realTime); + + const [tA, tB] = await Promise.all([doneA, doneB]); + assert.deepStrictEqual({ + aRoot: tA.root.label, + aLabels: traceInfo(tA).labels, + bRoot: tB.root.label, + bLabels: traceInfo(tB).labels, + }, { + aRoot: 'a', + aLabels: ['setTimeout(0ms)', 'a'], + bRoot: 'b', + bLabels: ['setTimeout(0ms)', 'b'], + }); + }); + + test('buildHistoryFromTasks adapter: scheduler history feeds the renderer', async () => { + const startTime = 1000; + const store = new DisposableStore(); + const scheduler = new TimeTravelScheduler(startTime); + const p = store.add(new AsyncSchedulerProcessor(scheduler, { maxTaskCount: 100 })); + const vt = createVirtualTimeApi(scheduler, { fakeRequestAnimationFrame: true }); + + const rootA = createTraceRoot('A'); + const rootB = createTraceRoot('B'); + + // A: setTimeout(+0) spawns rAF(+16) and setTimeout(+50); rAF(+16) → rAF(+32). + TraceContext.instance.runWithTrace(rootA, () => { + vt.setTimeout(() => { + vt.requestAnimationFrame!(() => { + vt.requestAnimationFrame!(() => { /* A deep paint */ }); + }); + vt.setTimeout(() => { /* A delayed work */ }, 50); + }, 0); + }); + + // B: setTimeout(+10) → rAF(+26) → setTimeout(+46). + TraceContext.instance.runWithTrace(rootB, () => { + vt.setTimeout(() => { + vt.requestAnimationFrame!(() => { + vt.setTimeout(() => { /* B work */ }, 20); + }); + }, 10); + }); + + await p.run(); + + const history = buildHistoryFromTasks(p.history, startTime); + assert.deepStrictEqual( + { + rootLabels: history.roots.map(r => r.label), + events: history.events.map(e => ({ + time: e.time, + label: e.label, + root: e.root.label, + parent: e.parent ? `${e.parent.label}@+${e.parent.time}` : undefined, + })), + }, + { + rootLabels: ['A', 'B'], + events: [ + { time: 0, label: 'setTimeout', root: 'A', parent: undefined }, + { time: 10, label: 'setTimeout', root: 'B', parent: undefined }, + { time: 16, label: 'requestAnimationFrame', root: 'A', parent: 'setTimeout@+0' }, + { time: 26, label: 'requestAnimationFrame', root: 'B', parent: 'setTimeout@+10' }, + { time: 32, label: 'requestAnimationFrame', root: 'A', parent: 'requestAnimationFrame@+16' }, + { time: 46, label: 'setTimeout', root: 'B', parent: 'requestAnimationFrame@+26' }, + { time: 50, label: 'setTimeout', root: 'A', parent: 'setTimeout@+0' }, + ], + }, + ); + + // Sanity check: the renderer still works on adapter output. Output + // correctness is covered by `executionGraph.test.ts`. + assert.ok(renderSwimlanes(history).length > 0); + + store.dispose(); + }); + + test('complex graph: async/await + setTimeout + setInterval + rAF interleave with preserved causality', async () => { + const startTime = 1000; + const store = new DisposableStore(); + const scheduler = new TimeTravelScheduler(startTime); + const p = store.add(new AsyncSchedulerProcessor(scheduler, { maxTaskCount: 200 })); + const vt = createVirtualTimeApi(scheduler, { fakeRequestAnimationFrame: true }); + const log = TraceContext.instance.log.bind(TraceContext.instance); + + const rootA = createTraceRoot('A'); + const rootB = createTraceRoot('B'); + + // A: setTimeout(+1) runs an async handler that, after a microtask, + // fans out into rAF (+16) and setInterval(10ms). The rAF callback + // itself awaits a microtask before scheduling a setTimeout(+20). + // The interval ticks twice and then clears itself. + TraceContext.instance.runWithTrace(rootA, () => { + vt.setTimeout(async () => { + log('A:start'); + await Promise.resolve(); + log('A:after-await'); + vt.requestAnimationFrame!(async () => { + log('A:rAF'); + await Promise.resolve(); + vt.setTimeout(() => log('A:post-rAF'), 20); + }); + let ticks = 0; + const id = vt.setInterval(() => { + ticks++; + log(`A:tick#${ticks}`); + if (ticks === 2) { vt.clearInterval(id); } + }, 10); + }, 1); + }); + + // B: setTimeout(+3) → rAF (+19) → setTimeout(+39). Starts close to A + // so the two roots' events interleave on the timeline. + TraceContext.instance.runWithTrace(rootB, () => { + vt.setTimeout(() => { + log('B:start'); + vt.requestAnimationFrame!(() => { + log('B:rAF'); + vt.setTimeout(() => log('B:post-rAF'), 20); + }); + }, 3); + }); + + await p.run(); + + const history = buildHistoryFromTasks(p.history, startTime, TraceContext.instance.takeLog()); + assert.deepStrictEqual( + { + rootLabels: history.roots.map(r => r.label), + events: history.events.map(e => ({ + time: e.time, + label: e.label, + root: e.root.label, + parent: e.parent ? `${e.parent.label}@+${e.parent.time}` : undefined, + })), + }, + { + rootLabels: ['A', 'B'], + events: [ + { time: 1, label: 'setTimeout', root: 'A', parent: undefined }, + { time: 1, label: 'log: A:start', root: 'A', parent: 'setTimeout@+1' }, + { time: 1, label: 'log: A:after-await', root: 'A', parent: 'setTimeout@+1' }, + { time: 3, label: 'setTimeout', root: 'B', parent: undefined }, + { time: 3, label: 'log: B:start', root: 'B', parent: 'setTimeout@+3' }, + { time: 11, label: 'setInterval (iteration 1)', root: 'A', parent: 'setTimeout@+1' }, + { time: 11, label: 'log: A:tick#1', root: 'A', parent: 'setInterval (iteration 1)@+11' }, + { time: 17, label: 'requestAnimationFrame', root: 'A', parent: 'setTimeout@+1' }, + { time: 17, label: 'log: A:rAF', root: 'A', parent: 'requestAnimationFrame@+17' }, + { time: 19, label: 'requestAnimationFrame', root: 'B', parent: 'setTimeout@+3' }, + { time: 19, label: 'log: B:rAF', root: 'B', parent: 'requestAnimationFrame@+19' }, + { time: 21, label: 'setInterval (iteration 2)', root: 'A', parent: 'setTimeout@+1' }, + { time: 21, label: 'log: A:tick#2', root: 'A', parent: 'setInterval (iteration 2)@+21' }, + { time: 37, label: 'setTimeout', root: 'A', parent: 'requestAnimationFrame@+17' }, + { time: 37, label: 'log: A:post-rAF', root: 'A', parent: 'setTimeout@+37' }, + { time: 39, label: 'setTimeout', root: 'B', parent: 'requestAnimationFrame@+19' }, + { time: 39, label: 'log: B:post-rAF', root: 'B', parent: 'setTimeout@+39' }, + ], + }, + ); + + // Sanity check: the renderer accepts the adapter output. + assert.ok(renderSwimlanes(history).length > 0); + + store.dispose(); + }); +}); + +function deferred(): { promise: Promise; resolve: (v: T) => void; reject: (e: unknown) => void } { + let resolve!: (v: T) => void; + let reject!: (e: unknown) => void; + const promise = new Promise((res, rej) => { resolve = res; reject = rej; }); + return { promise, resolve, reject }; +} diff --git a/src/vs/base/test/common/traceableTimeApi.ts b/src/vs/base/test/common/traceableTimeApi.ts new file mode 100644 index 00000000000..32853918445 --- /dev/null +++ b/src/vs/base/test/common/traceableTimeApi.ts @@ -0,0 +1,352 @@ +/*--------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All rights reserved. + * Licensed under the MIT License. See License.txt in the project root for license information. + *--------------------------------------------------------------------------------------------*/ + +import { BugIndicatingError } from '../../common/errors.js'; +import type { TimeApi } from './timeTravelScheduler.js'; + +/** + * # Trace / tracing time api — theory of operation + * + * ## The problem + * + * In a test runtime where many async activities interleave (parallel fixtures, + * timers, promise chains), we want to ask of any scheduled action: "who + * caused this?". Clean causal attribution is useful for: + * - debugging ("which fixture left this timer queued?"), + * - per-owner termination criteria ("queue drained *for my fixture*"), + * - attribution in error messages. + * + * ## The model + * + * A {@link Trace} is an immutable value identifying a causal chain: + * + * Trace = { id; parent?: Trace; label: string; stack?: string; root: Trace } + * + * Roots have no parent. Every non-root trace's `root` points back to the top + * of its chain. Traces are only created by user code, timer wrappers, or the + * scheduler — never implicitly. + * + * ## The runtime state: {@link TraceContext} + * + * A {@link TraceContext} owns the mutable "current frame" slot plus a + * boolean re-entry guard. Production code uses the shared + * {@link TraceContext.instance}; tests can construct fresh instances for + * full isolation. The slot is mutated by two primitives: + * + * - {@link TraceContext.runWithTrace}(t, fn): set current=t, run fn + * synchronously, restore previous frame on exit. Nesting is supported. + * Microtasks enqueued by fn that run *after* fn returns see the + * restored trace. Use only for bounded synchronous regions. + * + * - {@link TraceContext.runAsHandler}(t, fn, resetApi): set current=t, + * run fn, and + * **do not restore synchronously**. The trace is reset on the next + * macrotask via `resetApi.setTimeout(0)`, guarded by a sequence number. + * Any microtask drain that follows `fn` — including `await` continuations + * inside `fn` — inherits `t`. Throws if called while another runAsHandler + * is on the JS call stack. Use for timer callbacks and other async + * entry points (e.g. the fixture's render body). + * + * ## Why this works for attribution + * + * The JS event loop drains microtasks to completion between macrotasks. So + * any microtask enqueued during a macrotask runs with whatever `_currentTrace` + * that macrotask left behind. If that macrotask is a timer callback that + * used `runAsHandler(t, ...)`, every continuation during its drain sees `t`, + * and any timer scheduled during that drain captures `t` via the tracing + * TimeApi wrapper. + * + * Across macrotasks, the chain is preserved by the wrapper: each call to + * `setTimeout`/`setInterval`/`requestAnimationFrame` going through + * {@link createTracingTimeApi} captures the current trace at schedule time + * and re-installs it (as a child) via `runAsHandler` when the callback fires. + * + * ## Why the identity-guarded reset is correct + * + * Two macrotasks A, B firing back-to-back: + * + * [A] runAsHandler(t_A, fnA) -> _current = frame_A; schedule reset_A + * [micro drain] -> await continuations see t_A + * [B] runAsHandler(t_B, fnB) -> _current = frame_B; schedule reset_B + * [micro drain] -> await continuations see t_B + * [reset_A fires] -> sees _current !== frame_A -> no-op + * [reset_B fires] -> _current = frame_A.prev (or its prev) + * + * Each `runAsHandler` mints a fresh {@link Frame}, so the active-frame + * identity check rejects stale resets. This tolerates arbitrary + * interleaving of concurrent handlers (e.g. parallel fixtures) correctly. + * + * ## Caveat: sync re-entry is a bug + * + * `runAsHandler` throws if another `runAsHandler` is already on the JS + * stack. Timer callbacks never run nested on the same stack (the event + * loop runs one at a time), so this throw only fires for misuse (e.g. a + * handler synchronously calling another handler). Nested + * {@link runWithTrace} is always fine — it push/pops synchronously. + */ + +export class Trace { + private static _idCounter = 0; + + public readonly id: number = ++Trace._idCounter; + public readonly root: Trace; + public readonly depth: number; + public readonly createdAt: number = Date.now(); + + constructor( + public readonly parent: Trace | undefined, + public readonly label: string, + public readonly stack: string | undefined = undefined, + ) { + this.root = parent?.root ?? this; + this.depth = (parent?.depth ?? -1) + 1; + } + + child(label: string, stack?: string): Trace { + return new Trace(this, label, stack); + } + + /** + * Renders the causal chain as "#id label ← #id label ← … ← #id label". + */ + describe(): string { + const parts: string[] = []; + for (let t: Trace | undefined = this; t; t = t.parent) { + parts.push(`#${t.id} ${t.label}`); + } + return parts.join(' ← '); + } + + toString(): string { return this.describe(); } +} + +/** Sentinel root for "no known provenance". */ +export const ROOT_TRACE: Trace = new Trace(undefined, ''); + +export function createTraceRoot(label: string, stack?: string): Trace { + return new Trace(undefined, label, stack); +} + +// ============================================================================ +// TraceContext: encapsulated trace state +// ============================================================================ + +export interface TracingTimeApiOptions { + /** Capture a stack trace on every schedule call. Expensive; enable for + * debugging only. */ + readonly captureStacks?: boolean; + /** Observer hook. Called synchronously on schedule and on fire. */ + readonly onEvent?: (event: TracingTimeEvent) => void; +} + +export type TracingTimeEvent = + | { readonly kind: 'schedule'; readonly api: string; readonly trace: Trace; readonly delayMs?: number } + | { readonly kind: 'fire'; readonly api: string; readonly trace: Trace } + | { readonly kind: 'throw'; readonly api: string; readonly trace: Trace; readonly error: unknown }; + +/** + * A pushed/popped trace activation. A fresh `Frame` is minted by every + * `runWithTrace` / `runAsHandler` call; identity is what the deferred + * reset in `runAsHandler` uses to detect that it's stale. + */ +interface Frame { + readonly trace: Trace; + readonly prev: Frame | undefined; +} + +const ROOT_FRAME: Frame = { trace: ROOT_TRACE, prev: undefined }; + +/** + * Holds the mutable "current frame" slot and exposes the trace propagation + * primitives as methods. + * + * Invariants: + * - Reads (`currentTrace()`) are pure. + * - Writes happen only inside `runWithTrace` / `runAsHandler` bodies. + * - Each call mints a fresh {@link Frame} object. A scheduled reset only + * fires if `_current` still points at *its* frame — preventing a stale + * reset from clobbering a newer installation. + * - `_isHandlerRunning` is true iff a `runAsHandler` frame is on the JS + * call stack. It returns to false between macrotasks. + * + * Production callers go through {@link TraceContext.instance}. Tests may + * construct fresh instances to get full isolation. + */ +export class TraceContext { + /** Shared default context. Production callers use this. */ + public static readonly instance = new TraceContext(); + + private _current: Frame = ROOT_FRAME; + private _isHandlerRunning: boolean = false; + private _log: { trace: Trace; message: string }[] = []; + + currentTrace(): Trace { return this._current.trace; } + + /** + * Append `message` to an in-memory log, tagged with the current trace. + * Useful for tests that want to assert the interleaving of work across + * causally distinct roots. Drain via {@link takeLog}. + */ + log(message: string): void { + this._log.push({ trace: this._current.trace, message }); + } + + /** Drain and return all entries logged via {@link log}. */ + takeLog(): readonly { trace: Trace; message: string }[] { + const entries = this._log; + this._log = []; + return entries; + } + + /** + * Install `t` as the current trace for the synchronous duration of `fn`, + * then restore the previous trace. Nestable. Does NOT propagate `t` into + * microtasks enqueued by fn that run *after* fn returns. + * + * Use for bounded synchronous scopes (e.g. iterating a batch of tagged + * callbacks within a single tick). + */ + runWithTrace(t: Trace, fn: () => T): T { + const prev = this._current; + const next = { trace: t, prev }; + this._current = next; + try { + return fn(); + } finally { + if (this._current !== next) { + // eslint-disable-next-line no-unsafe-finally + throw new BugIndicatingError( + `traceableTimeApi: runWithTrace detected unexpected mutation. ` + + `current=${this._current.trace.describe()}, expected=${t.describe()}` + ); + } + this._current = prev; + } + } + + /** + * Install `t` as the current trace, run `fn`, and keep `t` installed + * through the microtask drain that follows. Restore the previous trace + * via an identity-guarded `resetApi.setTimeout(0)` so that awaited + * continuations within `fn` observe `t`. + * + * Throws if called while another `runAsHandler` frame is on the JS call + * stack (synchronous re-entry is a bug). + */ + runAsHandler(t: Trace, fn: () => T, resetApi: TimeApi): T { + if (this._isHandlerRunning) { + throw new Error( + `traceableTimeApi: re-entrant runAsHandler detected. ` + + `current=${this._current.trace.describe()}, incoming=${t.describe()}` + ); + } + const prev = this._current; + const next: Frame = { trace: t, prev }; + this._current = next; + this._isHandlerRunning = true; + try { + return fn(); + } finally { + this._isHandlerRunning = false; + // Do NOT restore synchronously: microtasks enqueued by fn (including + // awaited continuations) must observe `t`. Schedule an + // identity-guarded reset on the next macrotask via the raw + // real-time API. + // + // `_current !== next` is the normal case when handlers + // interleave: another `runAsHandler` ran between us scheduling + // this reset and it firing, so it pushed its own frame and + // queued its own reset that will do the restoring. Skipping + // here is correct — see the class doc "identity-guarded reset". + resetApi.setTimeout(() => { + if (this._current === next) { + this._current = prev; + } + }, 0); + } + } + + /** + * Wrap `wrapped` so that every scheduled callback is tagged with the + * current trace at schedule time, and re-installed via + * {@link runAsHandler} when it fires. `resetApi` is used to schedule + * trace resets and must be a real-time API (pointing it at a virtual + * API would prevent resets from ever firing). + * + * Re-entrancy with a virtual-time scheduler: do NOT stack this wrapper + * over a virtual-time `TimeApi`. The scheduler already installs traces + * via `runAsHandler` when it runs each task, and a second + * `runAsHandler` from this wrapper would trip the sync re-entry guard. + */ + createTracingTimeApi( + wrapped: TimeApi, + resetApi: TimeApi, + options: TracingTimeApiOptions = {}, + ): TimeApi { + const captureStacks = options.captureStacks ?? false; + const onEvent = options.onEvent; + + const capture = (label: string, delayMs?: number): Trace => { + const stack = captureStacks ? new Error().stack : undefined; + const t = this._current.trace.child(label, stack); + onEvent?.({ kind: 'schedule', api: label, trace: t, delayMs }); + return t; + }; + + const invoke = (trace: Trace, api: string, body: () => void): void => { + onEvent?.({ kind: 'fire', api, trace }); + try { + this.runAsHandler(trace, body, resetApi); + } catch (e) { + onEvent?.({ kind: 'throw', api, trace, error: e }); + throw e; + } + }; + + const api: TimeApi = { + Date: wrapped.Date, + setTimeout: (handler: () => void, ms?: number) => { + const t = capture(`setTimeout(${ms ?? 0}ms)`, ms); + return wrapped.setTimeout(() => invoke(t, 'setTimeout', handler), ms); + }, + clearTimeout: (id: unknown) => wrapped.clearTimeout(id), + setInterval: (handler: () => void, interval: number) => { + const base = capture(`setInterval(${interval}ms)`, interval); + let tickIdx = 0; + return wrapped.setInterval(() => { + const tickTrace = base.child(`tick #${++tickIdx}`); + invoke(tickTrace, 'setInterval', handler); + }, interval); + }, + clearInterval: (id: unknown) => wrapped.clearInterval(id), + }; + + if (wrapped.setImmediate) { + api.setImmediate = (handler: () => void) => { + const t = capture('setImmediate'); + return wrapped.setImmediate!(() => invoke(t, 'setImmediate', handler)); + }; + api.clearImmediate = (id: unknown) => wrapped.clearImmediate?.(id); + } + + if (wrapped.requestAnimationFrame) { + api.requestAnimationFrame = (cb: (time: number) => void) => { + const t = capture('requestAnimationFrame'); + return wrapped.requestAnimationFrame!(time => invoke(t, 'requestAnimationFrame', () => cb(time))); + }; + api.cancelAnimationFrame = (id: number) => wrapped.cancelAnimationFrame?.(id); + } + + api.originalFunctions = wrapped.originalFunctions ?? wrapped; + return api; + } + + /** Reset state. Only intended for tests. */ + _resetForTesting(): void { + this._current = ROOT_FRAME; + this._isHandlerRunning = false; + this._log = []; + } +} diff --git a/src/vs/workbench/test/browser/componentFixtures/fixtureUtils.ts b/src/vs/workbench/test/browser/componentFixtures/fixtureUtils.ts index 994662cb201..ece0d2e496f 100644 --- a/src/vs/workbench/test/browser/componentFixtures/fixtureUtils.ts +++ b/src/vs/workbench/test/browser/componentFixtures/fixtureUtils.ts @@ -6,21 +6,27 @@ // This should be the only place that is allowed to import from @vscode/component-explorer // eslint-disable-next-line local/code-import-patterns import { defineFixture, defineFixtureGroup, defineFixtureVariants } from '@vscode/component-explorer'; -import { DisposableStore, toDisposable } from '../../../../base/common/lifecycle.js'; +import { DisposableStore, DisposableTracker, setDisposableTracker, toDisposable } from '../../../../base/common/lifecycle.js'; import { URI } from '../../../../base/common/uri.js'; // eslint-disable-next-line local/code-import-patterns import '../../../../../../build/vite/style.css'; import '../../../browser/media/style.css'; +// Import auxiliaryBarPart.css here (before any contrib/chat CSS) so the cascade +// matches the product: chat.css loads later and overrides the auxiliarybar +// rules where applicable. Fixtures that wrap content in `.part.auxiliarybar` +// rely on these rules to recolor inline editors with `--vscode-sideBar-background`. +import '../../../browser/parts/auxiliarybar/media/auxiliaryBarPart.css'; // Theme import { IEnvironmentService } from '../../../../platform/environment/common/environment.js'; +import { IExtensionResourceLoaderService } from '../../../../platform/extensionResourceLoader/common/extensionResourceLoader.js'; import { Registry } from '../../../../platform/registry/common/platform.js'; import { getIconsStyleSheet } from '../../../../platform/theme/browser/iconsStyleSheet.js'; -import { ColorScheme } from '../../../../platform/theme/common/theme.js'; +import { ColorScheme, ThemeTypeSelector } from '../../../../platform/theme/common/theme.js'; import { IColorTheme, IThemeService, IThemingRegistry, Extensions as ThemingExtensions } from '../../../../platform/theme/common/themeService.js'; import { generateColorThemeCSS } from '../../../services/themes/browser/colorThemeCss.js'; import { ColorThemeData } from '../../../services/themes/common/colorThemeData.js'; -import { COLOR_THEME_DARK_INITIAL_COLORS, COLOR_THEME_LIGHT_INITIAL_COLORS } from '../../../services/themes/common/workbenchThemeService.js'; +import { ExtensionData } from '../../../services/themes/common/workbenchThemeService.js'; // Instantiation import { SyncDescriptor } from '../../../../platform/instantiation/common/descriptors.js'; @@ -82,6 +88,7 @@ import { IUndoRedoService } from '../../../../platform/undoRedo/common/undoRedo. import { UndoRedoService } from '../../../../platform/undoRedo/common/undoRedoService.js'; import { IUserDataProfile } from '../../../../platform/userDataProfile/common/userDataProfile.js'; import { IUserInteractionService, MockUserInteractionService } from '../../../../platform/userInteraction/browser/userInteractionService.js'; +import { IActionWidgetService } from '../../../../platform/actionWidget/browser/actionWidget.js'; import { IAnyWorkspaceIdentifier } from '../../../../platform/workspace/common/workspace.js'; import { TestMenuService } from '../workbenchTestServices.js'; import { IAccessibilitySignalService } from '../../../../platform/accessibilitySignal/browser/accessibilitySignalService.js'; @@ -102,7 +109,7 @@ import './fixtures.css'; // Import color registrations to ensure colors are available import { IdleDeadline, installFakeRunWhenIdle } from '../../../../base/common/async.js'; -import { AsyncSchedulerProcessor, TimeTravelScheduler, captureGlobalTimeApi, createLoggingTimeApi, createVirtualTimeApi, overwriteGlobalTimeApi } from '../../../../base/test/common/timeTravelScheduler.js'; +import { AsyncSchedulerProcessor, TimeTravelScheduler, captureGlobalTimeApi, createLoggingTimeApi, createVirtualTimeApi, pushGlobalTimeApi } from '../../../../base/test/common/timeTravelScheduler.js'; import '../../../../platform/theme/common/colors/baseColors.js'; import '../../../../platform/theme/common/colors/editorColors.js'; import '../../../../platform/theme/common/colors/listColors.js'; @@ -224,15 +231,55 @@ class NullStorageService implements IStorageService { const themingRegistry = Registry.as(ThemingExtensions.ThemingContribution); const mockEnvironmentService: IEnvironmentService = Object.create(null); -export const darkTheme = ColorThemeData.createUnloadedThemeForThemeType( - ColorScheme.DARK, - COLOR_THEME_DARK_INITIAL_COLORS -); +// Eagerly bundle all built-in theme JSON files so they can be served to +// `_loadColorTheme` via the IExtensionResourceLoaderService code path. The +// rspack config maps these JSON files to `asset/source`, so they are imported +// as raw text (not parsed JSON) — this lets VS Code's JSONC parser handle +// comments and trailing commas the way it does in the real product. +/* eslint-disable local/code-import-patterns */ +import dark_modern from '../../../../../../extensions/theme-defaults/themes/dark_modern.json' with { type: 'json' }; +import dark_plus from '../../../../../../extensions/theme-defaults/themes/dark_plus.json' with { type: 'json' }; +import dark_vs from '../../../../../../extensions/theme-defaults/themes/dark_vs.json' with { type: 'json' }; +import light_modern from '../../../../../../extensions/theme-defaults/themes/light_modern.json' with { type: 'json' }; +import light_plus from '../../../../../../extensions/theme-defaults/themes/light_plus.json' with { type: 'json' }; +import light_vs from '../../../../../../extensions/theme-defaults/themes/light_vs.json' with { type: 'json' }; +import { createTraceRoot, TraceContext } from '../../../../base/test/common/traceableTimeApi.js'; +/* eslint-enable local/code-import-patterns */ -export const lightTheme = ColorThemeData.createUnloadedThemeForThemeType( - ColorScheme.LIGHT, - COLOR_THEME_LIGHT_INITIAL_COLORS -); +const themeJsonModules: Record = { + '/extensions/theme-defaults/themes/dark_modern.json': dark_modern as unknown as string, + '/extensions/theme-defaults/themes/dark_plus.json': dark_plus as unknown as string, + '/extensions/theme-defaults/themes/dark_vs.json': dark_vs as unknown as string, + '/extensions/theme-defaults/themes/light_modern.json': light_modern as unknown as string, + '/extensions/theme-defaults/themes/light_plus.json': light_plus as unknown as string, + '/extensions/theme-defaults/themes/light_vs.json': light_vs as unknown as string, +}; + +const fixtureExtensionResourceLoaderService = new class implements IExtensionResourceLoaderService { + declare readonly _serviceBrand: undefined; + async readExtensionResource(uri: URI): Promise { + const content = themeJsonModules[uri.path]; + if (content === undefined) { + throw new Error(`Fixture extension resource not found: ${uri.toString()}`); + } + return content; + } + supportsExtensionGalleryResources(): Promise { return Promise.resolve(false); } + isExtensionGalleryResource(): Promise { return Promise.resolve(false); } + getExtensionGalleryResourceURL(): Promise { return Promise.resolve(undefined); } +}; + +function createBuiltInTheme(themePath: string, uiTheme: ThemeTypeSelector): ColorThemeData { + const location = URI.parse(`file://${themePath}`); + return ColorThemeData.fromExtensionTheme( + { id: themePath, path: themePath, uiTheme, _watch: false }, + location, + ExtensionData.fromName('vscode', 'theme-defaults', true) + ); +} + +export const darkTheme = createBuiltInTheme('/extensions/theme-defaults/themes/dark_modern.json', ThemeTypeSelector.VS_DARK); +export const lightTheme = createBuiltInTheme('/extensions/theme-defaults/themes/light_modern.json', ThemeTypeSelector.VS); let globalStyleSheet: CSSStyleSheet | undefined; let iconsStyleSheetCache: CSSStyleSheet | undefined; @@ -296,6 +343,17 @@ function getThemeStyleSheet(theme: ColorThemeData): CSSStyleSheet { let globalStylesInstalled = false; +let themesLoadedPromise: Promise | undefined; +function ensureThemesLoaded(): Promise { + if (!themesLoadedPromise) { + themesLoadedPromise = Promise.all([ + darkTheme.ensureLoaded(fixtureExtensionResourceLoaderService), + lightTheme.ensureLoaded(fixtureExtensionResourceLoaderService), + ]).then(() => undefined); + } + return themesLoadedPromise; +} + function installGlobalStyles(): void { if (globalStylesInstalled) { return; @@ -310,7 +368,8 @@ function installGlobalStyles(): void { ]; } -export function setupTheme(container: HTMLElement, theme: ColorThemeData): void { +export async function setupTheme(container: HTMLElement, theme: ColorThemeData): Promise { + await ensureThemesLoaded(); installGlobalStyles(); container.classList.add('monaco-workbench', getPlatformClass(), 'disable-animations', ...theme.classNames); } @@ -454,6 +513,13 @@ export function createEditorServices(disposables: DisposableStore, options?: Cre // User interaction service with focus simulation enabled (all elements appear focused in fixtures) defineInstance(IUserInteractionService, new MockUserInteractionService(true, false)); + definePartialInstance(IActionWidgetService, { + _serviceBrand: undefined, + show: () => { }, + hide: () => { }, + get isVisible() { return false; }, + }); + defineInstance(IAccessibilitySignalService, { _serviceBrand: undefined, playSignal: async () => { }, @@ -646,6 +712,7 @@ export interface ComponentFixtureContext { export interface ComponentFixtureOptions { render: (context: ComponentFixtureContext) => void | Promise; labels?: ThemedFixtureGroupLabels; + virtualTime?: { enabled?: boolean; durationMs?: number }; } type ThemedFixtures = ReturnType; @@ -653,11 +720,20 @@ type ThemedFixtures = ReturnType; // Permanent logging layer that detects real timer API usage. // Includes handler source for identification since bundled stack traces are not useful. const realTimeApi = captureGlobalTimeApi(); -const loggingTimeApi = createLoggingTimeApi(realTimeApi, (name, stack, handler) => { - const handlerStr = typeof handler === 'function' ? handler.toString().slice(0, 500) : String(handler); - console.warn(`[ComponentFixture] Real ${name} called outside of virtual time.\nHandler: ${handlerStr}\nStack: ${stack}`); -}); -overwriteGlobalTimeApi(loggingTimeApi); +const logOutsideTime = false; +if (logOutsideTime) { + const loggingTimeApi = createLoggingTimeApi(realTimeApi, (name, stack, handler) => { + const handlerStr = typeof handler === 'function' ? handler.toString().slice(0, 500) : String(handler); + console.warn(`[ComponentFixture] Real ${name} called outside of virtual time.\nHandler: ${handlerStr}\nStack: ${stack}`); + }); + pushGlobalTimeApi(loggingTimeApi); +} + +let fixtureRenderCounter = 0; + +// See TODO in defineComponentFixture: leak errors detected during teardown are +// stashed here and rethrown from the next fixture render. +let pendingLeakErrorToThrow: Error | undefined; /** * Creates Dark and Light fixture variants from a single render function. @@ -673,49 +749,117 @@ export function defineComponentFixture(options: ComponentFixtureOptions): Themed displayMode: { type: 'component' }, background: theme === darkTheme ? 'dark' : 'light', render: async (container: HTMLElement, context) => { - const disposableStore = context.addDisposable(new DisposableStore()); + // TODO: component-explorer currently ignores errors thrown from the + // teardown disposable (where leak detection runs, after the screenshot). + // Until it surfaces those, we stash the leak error and rethrow it from + // the next fixture render so the failure still becomes visible. + const pendingLeakError = pendingLeakErrorToThrow; + pendingLeakErrorToThrow = undefined; + if (pendingLeakError) { + throw pendingLeakError; + } - const schedulerStore = disposableStore.add(new DisposableStore()); - const scheduler = new TimeTravelScheduler(Date.now()); - const p = schedulerStore.add(new AsyncSchedulerProcessor(scheduler, { - maxTaskCount: 100, - realTimeApi, + const disposableStore = new DisposableStore(); + + // Do not enable virtual time in explorer ui, as multiple fixtures are rendered in parallel. + const virtualTimeEnabled = (options.virtualTime?.enabled ?? true) && context.host.kind !== 'explorer-ui'; + + // Detect disposable leaks the same way unit tests do (`ensureNoDisposablesAreLeakedInTestSuite`). + // The tracker is global and therefore unsafe when fixtures render in parallel, + // so it is only enabled outside the explorer UI (e.g. in screenshot/CI mode). + const leakDetectionEnabled = false && context.host.kind !== 'explorer-ui'; + const tracker = leakDetectionEnabled ? new DisposableTracker() : undefined; + if (tracker) { + setDisposableTracker(tracker); + } + + const leakLabel = `${(options.labels ? resolveLabels(options.labels).join('/') : '')}/${theme === darkTheme ? 'Dark' : 'Light'} (render#${fixtureRenderCounter + 1})`; + + context.addDisposable(toDisposable(() => { + disposableStore.dispose(); + if (tracker) { + setDisposableTracker(null); + const result = tracker.computeLeakingDisposables(); + if (result) { + console.error(result.details); + pendingLeakErrorToThrow = new Error(`[leak detected in previous fixture: ${leakLabel}] There are ${result.leaks.length} undisposed disposables!${result.details}`); + } + } })); async function actualRender() { - - setupTheme(container, theme); - - const virtualTimeApi = createVirtualTimeApi(scheduler, { fakeRequestAnimationFrame: true }); - schedulerStore.add(overwriteGlobalTimeApi(virtualTimeApi)); - disposableStore.add(installFakeRunWhenIdle((_targetWindow, callback, _timeout?) => { - return scheduler.schedule({ - time: scheduler.now, - run: () => { - const deadline: IdleDeadline = { - didTimeout: true, - timeRemaining: () => 50, - }; - callback(deadline); - }, - source: { - toString() { return 'runWhenIdle'; }, - stackTrace: undefined, - }, - }); + const schedulerStore = disposableStore.add(new DisposableStore()); + const scheduler = new TimeTravelScheduler(Date.now()); + const p = schedulerStore.add(new AsyncSchedulerProcessor(scheduler, { + maxTaskCount: 100, + realTimeApi, })); - const result = options.render({ container, disposableStore, theme }); + await setupTheme(container, theme); - const p2 = p.runForVirtualTimeMs(1000); + const virtualTimeApi = createVirtualTimeApi(scheduler, { fakeRequestAnimationFrame: true }); - await Promise.all([ - result instanceof Promise ? result : Promise.resolve(), - p2, - ]); + if (virtualTimeEnabled) { + schedulerStore.add(pushGlobalTimeApi(virtualTimeApi)); + + disposableStore.add(installFakeRunWhenIdle((_targetWindow, callback, _timeout?) => { + const stackTrace = new Error().stack; + const trace = TraceContext.instance.currentTrace().child('runWhenIdle', stackTrace); + return scheduler.schedule({ + time: scheduler.now, + run: () => { + const deadline: IdleDeadline = { + didTimeout: true, + timeRemaining: () => 50, + }; + callback(deadline); + }, + source: { + toString() { return 'runWhenIdle'; }, + stackTrace, + }, + trace, + }); + })); + } + + try { + const result = options.render({ container, disposableStore, theme }); + + const p2 = virtualTimeEnabled + ? p.run({ virtualDeadline: scheduler.now + (options.virtualTime?.durationMs ?? 1000), maxTasks: 100, maxTaskDepth: 5 }) + : Promise.resolve(); + + await Promise.all([ + result instanceof Promise ? result : Promise.resolve(), + p2, + ]); + } finally { + if (virtualTimeEnabled && p.history.length > 0) { + // TODO + // const startTime = p.history[0].time; + // const history = buildHistoryFromTasks(p.history, startTime); + // console.log(`[ComponentFixture] ${themeLabel} virtual-time history (${p.history.length} tasks):\n${renderSwimlanes(history)}`); + } + schedulerStore.dispose(); + } + + const drain = false; + if (drain) { + disposableStore.add(toDisposable(() => { + p.run({ maxTasks: 100, maxTaskDepth: 5 }); + })); + } } - await actualRender(); + // Every render gets its own trace root so that any diagnostics + // output by the scheduler / processor shows exactly which fixture + // caused each queued or historical timer, plus the full chain of + // setTimeout/rAF calls that led to it. + const themeLabel = theme === darkTheme ? 'Dark' : 'Light'; + const fixtureRoot = createTraceRoot(`render#${++fixtureRenderCounter}(${themeLabel})`); + + await TraceContext.instance.runAsHandler(fixtureRoot, actualRender, realTimeApi); }, });