diff --git a/desktop/src/shared/profiling/drift.ts b/desktop/src/shared/profiling/drift.ts index 098874b0a..72e0af38d 100644 --- a/desktop/src/shared/profiling/drift.ts +++ b/desktop/src/shared/profiling/drift.ts @@ -1,13 +1,26 @@ -// Temporary renderer profiling harness (never merges) — event-loop drift math. +// Temporary renderer profiling harness (never merges) — sampling math. // -// WebKit exposes no Long Tasks API, so main-thread stalls are inferred from -// timer drift: a timer armed for `intervalMs` that fires late by more than -// `thresholdMs` means the main thread was blocked for roughly that overage. +// Pure, deterministic decision helpers for the two DOM-driven probes so the +// harness wiring stays thin and the judgement is unit-testable without loading +// the harness's Tauri/store imports: +// - main-thread stalls, inferred from timer drift (WebKit has no Long Tasks +// API): a timer armed for `intervalMs` that fires late by more than +// `thresholdMs` means the main thread was blocked for roughly that overage; +// - input latency, split into the pre-dispatch queue delay and the +// post-receipt paint delay. /** Default sampling interval for the drift timer. */ export const DRIFT_INTERVAL_MS = 500; /** Report a stall only when drift exceeds this — filters normal scheduler jitter. */ export const DRIFT_THRESHOLD_MS = 50; +/** Record an input event only when its total felt latency reaches this. */ +export const INPUT_LATENCY_MIN_MS = 100; +/** + * Largest plausible pre-dispatch age. A larger (or negative) `event.timeStamp` + * → `performance.now()` delta means the two are on different clock bases, so + * the queue figure is dropped rather than trusted. + */ +export const MAX_INPUT_QUEUED_MS = 60_000; /** * Overage of an observed timer fire versus its expected fire time. @@ -24,3 +37,51 @@ export function computeDrift( const drift = observed - expected; return drift > thresholdMs ? drift : null; } + +/** + * Judge one drift interval and re-arm the baseline. + * + * `eligible` is false whenever the interval did not both begin and end in the + * visible, focused foreground (a hidden/occluded/asleep webview defers timers, + * and that deferral must never be attributed to a main-thread block). An + * ineligible interval records nothing but still re-arms `armedAt` to `observed` + * so the first foreground interval after a return cannot manufacture a phantom + * stall from the accumulated background gap. + */ +export function nextStallSample( + armedAt: number, + observed: number, + eligible: boolean, + intervalMs: number = DRIFT_INTERVAL_MS, + thresholdMs: number = DRIFT_THRESHOLD_MS, +): { dur: number | null; armedAt: number } { + const dur = eligible + ? computeDrift(observed, armedAt + intervalMs, thresholdMs) + : null; + return { dur, armedAt: observed }; +} + +/** + * Split an input event's felt latency into its two additive parts and decide + * whether it clears the recording threshold. + * + * `latency` is `paintedAt - receivedAt`: the capture-phase listener's receipt + * (a `performance.now()` read taken synchronously in the listener) to the next + * painted frame. `queued` is `receivedAt - eventTimeStamp`: the pre-dispatch + * delay — the dominant signal when a busy main thread stalls event dispatch — + * or `null` when that delta is implausible (a clock-basis mismatch). The event + * is recorded when the total felt latency (`latency + queued`) reaches `minMs`. + */ +export function classifyInput( + eventTimeStamp: number, + receivedAt: number, + paintedAt: number, + minMs: number = INPUT_LATENCY_MIN_MS, +): { latency: number; queued: number | null } | null { + const latency = paintedAt - receivedAt; + const rawQueued = receivedAt - eventTimeStamp; + const queued = + rawQueued >= 0 && rawQueued <= MAX_INPUT_QUEUED_MS ? rawQueued : null; + const felt = latency + (queued ?? 0); + return felt >= minMs ? { latency, queued } : null; +} diff --git a/desktop/src/shared/profiling/harness.test.mjs b/desktop/src/shared/profiling/harness.test.mjs index ecb8e3f89..5efa4f077 100644 --- a/desktop/src/shared/profiling/harness.test.mjs +++ b/desktop/src/shared/profiling/harness.test.mjs @@ -10,7 +10,12 @@ import assert from "node:assert/strict"; import { describe, it } from "node:test"; -import { computeDrift, DRIFT_THRESHOLD_MS } from "@/shared/profiling/drift.ts"; +import { + classifyInput, + computeDrift, + DRIFT_THRESHOLD_MS, + nextStallSample, +} from "@/shared/profiling/drift.ts"; import { ProfileRecorder, RING_CAPACITY } from "@/shared/profiling/recorder.ts"; function fixedClock() { @@ -37,6 +42,56 @@ describe("computeDrift", () => { }); }); +describe("nextStallSample", () => { + it("records a real overrun in an eligible (foreground) interval", () => { + // armed at 1000, interval 500 → expected 1500; observed 1800 → 300 overrun. + const { dur, armedAt } = nextStallSample(1000, 1800, true, 500, 50); + assert.equal(dur, 300); + assert.equal(armedAt, 1800); + }); + + it("suppresses the record but re-arms the baseline when ineligible", () => { + // A hidden/blurred interval defers the timer arbitrarily; the huge gap must + // not be scored, but armedAt must advance so the next interval is clean. + const { dur, armedAt } = nextStallSample(1000, 60_000, false, 500, 50); + assert.equal(dur, null); + assert.equal(armedAt, 60_000); + }); + + it("cannot manufacture a phantom stall on the interval after a return", () => { + // Background interval [1000, 60000] re-armed to 60000 with no record. + const background = nextStallSample(1000, 60_000, false, 500, 50); + // First foreground interval fires on time from the re-armed baseline. + const resumed = nextStallSample(background.armedAt, 60_500, true, 500, 50); + assert.equal(resumed.dur, null); + }); +}); + +describe("classifyInput", () => { + it("splits felt latency into paint delay and pre-dispatch queue", () => { + // event@100, received@250 (queued 150), painted@300 (latency 50) → felt 200. + const result = classifyInput(100, 250, 300); + assert.deepEqual(result, { latency: 50, queued: 150 }); + }); + + it("drops the queue figure when the clock basis is implausible", () => { + // event.timeStamp on a different origin: received - timeStamp is negative. + const result = classifyInput(9_999_999, 250, 400); + assert.deepEqual(result, { latency: 150, queued: null }); + }); + + it("returns null when total felt latency is under threshold", () => { + // queued 10 + latency 20 = 30ms felt, below the 100ms floor. + assert.equal(classifyInput(100, 110, 130), null); + }); + + it("uses only paint latency toward the threshold when queue is implausible", () => { + // queued dropped (negative); latency 120 alone clears the floor. + const result = classifyInput(9_999_999, 250, 370); + assert.deepEqual(result, { latency: 120, queued: null }); + }); +}); + describe("ProfileRecorder ring buffer", () => { it("bounds the buffer at RING_CAPACITY, dropping oldest", async () => { const rec = new ProfileRecorder("session-1", async () => {}, fixedClock()); diff --git a/desktop/src/shared/profiling/harness.ts b/desktop/src/shared/profiling/harness.ts index 7bf287ece..4795cac68 100644 --- a/desktop/src/shared/profiling/harness.ts +++ b/desktop/src/shared/profiling/harness.ts @@ -2,7 +2,8 @@ // // One always-on harness that ring-buffers timing records and flushes JSONL to // `/profiling/session-.jsonl`. Four probes: -// 1. main-thread stalls (timer drift) + input latency (down → next paint) +// 1. main-thread stalls (timer drift, foreground-only) + input latency +// (receipt → next paint, with pre-dispatch queue delay split out) // 2. Tauri IPC duration/outcome + a >10s pending-invoke watchdog (deadlocks) // 3. relay REQ→EOSE (history fetch) and publish send→ack round-trips // 4. periodic accumulator census (observer store, query cache, DOM nodes) @@ -18,8 +19,8 @@ import { getObserverStoreCensus } from "@/features/agents/observerRelayStore"; import { relayClient } from "@/shared/api/relayClient"; import { DRIFT_INTERVAL_MS, - DRIFT_THRESHOLD_MS, - computeDrift, + classifyInput, + nextStallSample, } from "@/shared/profiling/drift"; import { FLUSH_INTERVAL_MS, @@ -29,7 +30,6 @@ import { const CENSUS_INTERVAL_MS = 120_000; const PENDING_INVOKE_MS = 10_000; const PENDING_SCAN_MS = 5_000; -const INPUT_LATENCY_MIN_MS = 100; // RelayClient methods whose resolution marks a REQ→EOSE round-trip (history // fetches resolve when the relay sends EOSE) versus a publish send→ack @@ -137,35 +137,60 @@ function installIpcProbe(rec: ProfileRecorder): void { }, PENDING_SCAN_MS); } +function isForeground(): boolean { + return document.visibilityState === "visible" && document.hasFocus(); +} + function installStallProbe(rec: ProfileRecorder): void { let armedAt = performance.now(); + // An interval only counts if the document stayed visible+focused for its + // whole span. Any blur/hide between arms taints the current interval so a + // background gap is never scored as a main-thread block. + let continuousForeground = isForeground(); + const taint = () => { + continuousForeground = false; + }; + document.addEventListener("visibilitychange", taint); + window.addEventListener("blur", taint); window.setInterval(() => { const observed = performance.now(); - const drift = computeDrift( - observed, - armedAt + DRIFT_INTERVAL_MS, - DRIFT_THRESHOLD_MS, - ); - if (drift !== null) { - rec.record({ type: "stall", dur: drift }); + const eligible = continuousForeground && isForeground(); + const sample = nextStallSample(armedAt, observed, eligible); + if (sample.dur !== null) { + rec.record({ type: "stall", dur: sample.dur }); } - armedAt = observed; + armedAt = sample.armedAt; + // Re-arm cleanly: the next interval is continuous only if we are in the + // foreground right now. + continuousForeground = isForeground(); }, DRIFT_INTERVAL_MS); } function installInputProbe(rec: ProfileRecorder): void { const onInput = (kind: "keydown" | "pointerdown") => (event: Event) => { - const start = event.timeStamp; + // Capture the harness's own receipt clock synchronously, in the listener, + // so `latency` is receipt → next painted frame on a single clock basis. + const receivedAt = performance.now(); + const eventTimeStamp = event.timeStamp; requestAnimationFrame(() => requestAnimationFrame(() => { - const latency = performance.now() - start; - if (latency >= INPUT_LATENCY_MIN_MS) { - rec.record({ type: "input", kind, latency }); + const result = classifyInput( + eventTimeStamp, + receivedAt, + performance.now(), + ); + if (result !== null) { + rec.record({ + type: "input", + kind, + latency: result.latency, + queued: result.queued, + }); } }), ); }; - // Capture phase so the timestamp precedes app handlers. + // Capture phase so the receipt clock precedes app handlers. window.addEventListener("keydown", onInput("keydown"), { capture: true, passive: true, diff --git a/desktop/src/shared/profiling/types.ts b/desktop/src/shared/profiling/types.ts index 54d789ff0..13a1c6044 100644 --- a/desktop/src/shared/profiling/types.ts +++ b/desktop/src/shared/profiling/types.ts @@ -24,8 +24,14 @@ export type StallRecord = ProfileEnvelope & { export type InputRecord = ProfileEnvelope & { type: "input"; kind: "keydown" | "pointerdown"; - /** Event timestamp → next painted frame, ms. */ + /** Capture-listener receipt → next painted frame, ms (single-clock). */ latency: number; + /** + * Pre-dispatch delay: `event.timeStamp` → capture-listener receipt, ms. + * `null` when that delta is implausible (a cross-clock basis mismatch). + * Total felt latency is `latency + (queued ?? 0)`. + */ + queued: number | null; }; export type IpcRecord = ProfileEnvelope & {