fix(desktop): correct stall foreground gating and input latency clock

Two measurement-validity fixes to the profiling harness (review pass):

- Stall probe scored timer deferral from a hidden/occluded/asleep webview
  as a main-thread block, so a single wake could emit an arbitrarily large
  dur dominating the ranked total. Gate drift records on continuous
  visible+focused foreground and re-arm the baseline across background
  windows so the first post-return interval cannot manufacture a phantom
  stall.
- Input latency used performance.now() - event.timeStamp, folding
  pre-dispatch/OS-queue delay into the figure on a cross-clock assumption.
  Capture the listener's own receipt clock synchronously; latency is now
  receipt to next painted frame on one clock, with the pre-dispatch queue
  delay split into a separate queued field (dropped when the clock basis
  is implausible).

Co-authored-by: Will Pfleger <pfleger.will@gmail.com>
Signed-off-by: Will Pfleger <pfleger.will@gmail.com>
This commit is contained in:
Duncan
2026-08-17 20:08:05 -04:00
co-authored by Will Pfleger
parent a811bea73a
commit caf53aa541
4 changed files with 170 additions and 23 deletions
+65 -4
View File
@@ -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;
}
+56 -1
View File
@@ -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());
+42 -17
View File
@@ -2,7 +2,8 @@
//
// One always-on harness that ring-buffers timing records and flushes JSONL to
// `<app-data>/profiling/session-<ts>.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,
+7 -1
View File
@@ -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 & {