feat(desktop): add temporary renderer profiling harness

Passive, always-on harness that ring-buffers timing records and flushes
JSONL to a local file in the app data dir. Four probes attribute felt
renderer lag: main-thread stalls (timer drift) plus input latency, Tauri
IPC duration/outcome with a >10s pending-invoke watchdog, relay
REQ->EOSE and publish send->ack round-trips, and a periodic accumulator
census. Nothing is transmitted; the JSONL file is the only output.

This branch is a measurement instrument and is not intended to merge.

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 f8692fa9b5
commit a811bea73a
10 changed files with 696 additions and 2 deletions
+2
View File
@@ -46,6 +46,7 @@ pub mod pairing;
mod personas;
mod prevent_sleep;
mod profile;
mod profiling_log;
mod project_git;
mod project_git_branches;
mod project_git_diff;
@@ -104,6 +105,7 @@ pub use pairing::*;
pub use personas::*;
pub use prevent_sleep::*;
pub use profile::*;
pub use profiling_log::*;
pub use project_git::*;
pub use project_git_branches::*;
pub use project_git_diff::*;
@@ -0,0 +1,96 @@
//! Local sink for the temporary renderer profiling harness (never merges).
//!
//! The renderer ring-buffers timing records and flushes JSONL lines here every
//! ~30s and on `pagehide`. Records are appended to
//! `<app-data>/profiling/<file_stem>.jsonl`. Nothing is transmitted; this file
//! is the only output. When a file crosses `MAX_FILE_BYTES` it is rotated aside
//! with a millisecond suffix so a long session cannot grow unbounded -- the
//! analyzer globs `<file_stem>*.jsonl` and concatenates.
use std::fs::{self, OpenOptions};
use std::io::Write;
use tauri::{AppHandle, Manager};
/// Rotate the active file aside once it reaches ~50 MiB.
const MAX_FILE_BYTES: u64 = 50 * 1024 * 1024;
/// Append profiling records (one JSONL string per element) to the session file.
///
/// `file_stem` is caller-supplied but strictly validated to
/// `session-<digits>` so the argument can never escape the profiling dir.
#[tauri::command]
pub async fn append_profiling_log(
file_stem: String,
lines: Vec<String>,
app: AppHandle,
) -> Result<(), String> {
if lines.is_empty() {
return Ok(());
}
if !is_valid_stem(&file_stem) {
return Err(format!("invalid profiling file stem: {file_stem}"));
}
tokio::task::spawn_blocking(move || {
let dir = app
.path()
.app_data_dir()
.map_err(|error| error.to_string())?
.join("profiling");
fs::create_dir_all(&dir).map_err(|error| error.to_string())?;
let path = dir.join(format!("{file_stem}.jsonl"));
if let Ok(meta) = fs::metadata(&path) {
if meta.len() >= MAX_FILE_BYTES {
let rolled = dir.join(format!(
"{file_stem}.{}.jsonl",
std::time::SystemTime::now()
.duration_since(std::time::UNIX_EPOCH)
.map(|d| d.as_millis())
.unwrap_or(0)
));
fs::rename(&path, rolled).map_err(|error| error.to_string())?;
}
}
let mut file = OpenOptions::new()
.create(true)
.append(true)
.open(&path)
.map_err(|error| error.to_string())?;
let mut buffer = String::new();
for line in &lines {
buffer.push_str(line);
buffer.push('\n');
}
file.write_all(buffer.as_bytes())
.map_err(|error| error.to_string())?;
Ok(())
})
.await
.map_err(|error| format!("spawn_blocking failed: {error}"))?
}
/// Accept only `session-<digits>` to keep the argument inside the sink dir.
fn is_valid_stem(stem: &str) -> bool {
stem.strip_prefix("session-")
.is_some_and(|rest| !rest.is_empty() && rest.bytes().all(|b| b.is_ascii_digit()))
}
#[cfg(test)]
mod tests {
use super::is_valid_stem;
#[test]
fn accepts_session_timestamp_stem() {
assert!(is_valid_stem("session-1700000000000"));
}
#[test]
fn rejects_traversal_and_malformed_stems() {
assert!(!is_valid_stem("session-../etc/passwd"));
assert!(!is_valid_stem("session-"));
assert!(!is_valid_stem("other-123"));
assert!(!is_valid_stem("session-12a"));
}
}
+2 -2
View File
@@ -148,8 +148,7 @@ pub fn run() {
}
// Linux/WebKitGTK needs media-stream settings and a
// permission-request handler for getUserMedia; no-op
// on macOS/Windows.
// permission-request handler for getUserMedia; no-op on macOS/Windows.
linux_media::enable_media_capture(&webview);
// macOS applies the restored geometry asynchronously. Wait
@@ -670,6 +669,7 @@ pub fn run() {
search_users,
get_presence,
get_os_idle_seconds,
append_profiling_log,
get_default_relay_url,
auto_connect_default_relay_enabled,
get_legacy_workspace_storage,
+5
View File
@@ -61,6 +61,7 @@ import { CommunityChangeOverlay } from "@/features/communities/ui/CommunityChang
import { setAvatarProfileSyncQueryClient } from "@/features/profile/avatarProfileSync";
import { EncryptedBackupProvider } from "@/features/settings/EncryptedBackupProvider";
import { createBuzzQueryClient } from "@/shared/api/queryClient";
import { startProfilingHarness } from "@/shared/profiling/harness";
import { isSharedIdentity as isSharedIdentityCmd } from "@/shared/api/tauri";
import { getProfile } from "@/shared/api/tauriProfiles";
import {
@@ -215,6 +216,10 @@ function CommunityQueryProvider({ children }: { children: ReactNode }) {
useEffect(() => setAvatarProfileSyncQueryClient(queryClient), [queryClient]);
// Temporary profiling harness (never merges): start once with a live
// QueryClient so the accumulator census can read the query cache.
useEffect(() => startProfilingHarness(queryClient), [queryClient]);
useEffect(() => {
const e2eWindow = window as Window & {
__BUZZ_E2E__?: unknown;
@@ -924,3 +924,38 @@ export function _testGetArchivedChannelEvents(
archiveEventsByChannel.get(archiveChannelKey(agentPubkey, channelId)) ?? []
);
}
/**
* Profiling-harness accessor (temporary branch): cheap size census of the
* module-level accumulator maps. Reads `.length`/`.size` only no allocation,
* no copy so it is safe to sample every couple of minutes. Feeds the
* `census` profiling record that adjudicates whether accumulator growth
* correlates with felt lag.
*/
export function getObserverStoreCensus(): {
observerEvents: number;
observerAgents: number;
observerMaxPerAgent: number;
archiveEvents: number;
transcripts: number;
} {
let observerEvents = 0;
let observerMaxPerAgent = 0;
for (const events of eventsByAgent.values()) {
observerEvents += events.length;
if (events.length > observerMaxPerAgent) {
observerMaxPerAgent = events.length;
}
}
let archiveEvents = 0;
for (const events of archiveEventsByChannel.values()) {
archiveEvents += events.length;
}
return {
observerEvents,
observerAgents: eventsByAgent.size,
observerMaxPerAgent,
archiveEvents,
transcripts: transcriptByAgent.size,
};
}
+26
View File
@@ -0,0 +1,26 @@
// Temporary renderer profiling harness (never merges) — event-loop drift 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.
/** 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;
/**
* Overage of an observed timer fire versus its expected fire time.
*
* `expected` is `armedAt + intervalMs`; `observed` is the actual fire time.
* Returns the non-negative main-thread block estimate, or `null` when the
* fire is within threshold (no stall worth recording).
*/
export function computeDrift(
observed: number,
expected: number,
thresholdMs: number = DRIFT_THRESHOLD_MS,
): number | null {
const drift = observed - expected;
return drift > thresholdMs ? drift : null;
}
@@ -0,0 +1,111 @@
/**
* Harness-core tests for the temporary renderer profiling branch (never merges).
*
* Scope is the pure, deterministic core only: ring-buffer bounds + flush
* draining, drift-sampler math, and the JSONL record schema. The DOM/timer/IPC
* probes are integration glue exercised by Will's day of driving, not unit
* tests.
*/
import assert from "node:assert/strict";
import { describe, it } from "node:test";
import { computeDrift, DRIFT_THRESHOLD_MS } from "@/shared/profiling/drift.ts";
import { ProfileRecorder, RING_CAPACITY } from "@/shared/profiling/recorder.ts";
function fixedClock() {
let t = 1000;
return {
now: () => (t += 1),
wall: () => 1_700_000_000_000,
};
}
describe("computeDrift", () => {
it("returns null when the fire is within threshold", () => {
assert.equal(computeDrift(1050, 1000, 100), null);
// Exactly at threshold is not a stall (strictly greater).
assert.equal(computeDrift(1000 + DRIFT_THRESHOLD_MS, 1000), null);
});
it("returns the overage when the timer fires late past threshold", () => {
assert.equal(computeDrift(1200, 1000, 50), 200);
});
it("treats early fires as no stall", () => {
assert.equal(computeDrift(980, 1000, 50), null);
});
});
describe("ProfileRecorder ring buffer", () => {
it("bounds the buffer at RING_CAPACITY, dropping oldest", async () => {
const rec = new ProfileRecorder("session-1", async () => {}, fixedClock());
for (let i = 0; i < RING_CAPACITY + 50; i++) {
rec.record({ type: "stall", dur: i });
}
assert.equal(rec.size(), RING_CAPACITY);
});
it("flushes serialized JSONL lines and drains the buffer", async () => {
const captured = [];
const rec = new ProfileRecorder(
"session-1",
async (lines) => {
captured.push(...lines);
},
fixedClock(),
);
rec.record({ type: "stall", dur: 42 });
rec.record({
type: "census",
observerEvents: 5,
observerAgents: 1,
observerMaxPerAgent: 5,
archiveEvents: 0,
transcripts: 1,
queryCache: 3,
domNodes: 100,
});
await rec.flush();
assert.equal(rec.size(), 0);
assert.equal(captured.length, 2);
const first = JSON.parse(captured[0]);
assert.equal(first.type, "stall");
assert.equal(first.dur, 42);
assert.equal(first.sid, "session-1");
assert.equal(typeof first.t, "number");
assert.equal(typeof first.wall, "number");
assert.equal(typeof first.up, "number");
});
it("stamps the drop count onto the first line after overflow", async () => {
const captured = [];
const rec = new ProfileRecorder(
"session-1",
async (lines) => {
captured.push(...lines);
},
fixedClock(),
);
for (let i = 0; i < RING_CAPACITY + 10; i++) {
rec.record({ type: "stall", dur: i });
}
await rec.flush();
const first = JSON.parse(captured[0]);
assert.equal(first.dropped, 10);
});
it("does not throw when the sink rejects, and still drains", async () => {
const rec = new ProfileRecorder(
"session-1",
async () => {
throw new Error("sink down");
},
fixedClock(),
);
rec.record({ type: "stall", dur: 1 });
await rec.flush();
assert.equal(rec.size(), 0);
});
});
+227
View File
@@ -0,0 +1,227 @@
// Temporary renderer profiling harness (never merges) — bootstrap + probes.
//
// 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)
// 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)
//
// The relay probe wraps the `relayClient` singleton's public methods (below),
// so `relayClientSession.ts` is untouched and no probe lines land in request
// code.
import type { QueryClient } from "@tanstack/react-query";
import { invoke } from "@tauri-apps/api/core";
import { getObserverStoreCensus } from "@/features/agents/observerRelayStore";
import { relayClient } from "@/shared/api/relayClient";
import {
DRIFT_INTERVAL_MS,
DRIFT_THRESHOLD_MS,
computeDrift,
} from "@/shared/profiling/drift";
import {
FLUSH_INTERVAL_MS,
ProfileRecorder,
} from "@/shared/profiling/recorder";
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
// round-trip (resolves on the relay's OK). All publishes funnel through
// `publishEvent`, and the instance-property wrap shadows the prototype so
// internal `this.publishEvent` calls are captured too — wrapping the public
// send* wrappers as well would double-count. Wrapping the singleton keeps the
// probe out of the grandfathered relayClientSession.ts and adds zero lines to
// production request code.
const RELAY_FETCH_METHODS = [
"fetchChannelHistory",
"fetchChannelHistoryBefore",
"fetchAuxEventsByReference",
"fetchAuxDeletionEventsForAuxEvents",
"fetchEvents",
"fetchFirstEvent",
] as const;
const RELAY_PUBLISH_METHODS = ["publishEvent"] as const;
let started = false;
type AsyncMethod = (...args: unknown[]) => Promise<unknown>;
function wrapRelayMethod(
rec: ProfileRecorder,
method: string,
type: "relay_req" | "relay_pub",
): void {
const target = relayClient as unknown as Record<string, unknown>;
const original = target[method];
if (typeof original !== "function") {
return;
}
const bound = (original as AsyncMethod).bind(relayClient);
target[method] = (...args: unknown[]) => {
const startedAt = performance.now();
const done = (ok: boolean) =>
rec.record({ type, op: method, dur: performance.now() - startedAt, ok });
return bound(...args).then(
(value) => {
done(true);
return value;
},
(error) => {
done(false);
throw error;
},
);
};
}
function installRelayProbe(rec: ProfileRecorder): void {
for (const method of RELAY_FETCH_METHODS) {
wrapRelayMethod(rec, method, "relay_req");
}
for (const method of RELAY_PUBLISH_METHODS) {
wrapRelayMethod(rec, method, "relay_pub");
}
}
type TauriInternals = {
invoke: (cmd: string, args?: unknown, opts?: unknown) => Promise<unknown>;
};
function installIpcProbe(rec: ProfileRecorder): void {
const internals = (
window as unknown as { __TAURI_INTERNALS__?: TauriInternals }
).__TAURI_INTERNALS__;
if (!internals || typeof internals.invoke !== "function") {
return;
}
const original = internals.invoke.bind(internals);
// Track outstanding invokes so a hung command surfaces via the watchdog.
const pending = new Map<number, { cmd: string; startedAt: number }>();
let seq = 0;
internals.invoke = (cmd: string, args?: unknown, opts?: unknown) => {
const id = seq++;
const startedAt = performance.now();
pending.set(id, { cmd, startedAt });
const settle = (ok: boolean) => {
pending.delete(id);
rec.record({ type: "ipc", cmd, dur: performance.now() - startedAt, ok });
};
return original(cmd, args, opts).then(
(value) => {
settle(true);
return value;
},
(error) => {
settle(false);
throw error;
},
);
};
window.setInterval(() => {
const now = performance.now();
for (const { cmd, startedAt } of pending.values()) {
const age = now - startedAt;
if (age > PENDING_INVOKE_MS) {
rec.record({ type: "ipc_pending", cmd, age });
}
}
}, PENDING_SCAN_MS);
}
function installStallProbe(rec: ProfileRecorder): void {
let armedAt = performance.now();
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 });
}
armedAt = observed;
}, DRIFT_INTERVAL_MS);
}
function installInputProbe(rec: ProfileRecorder): void {
const onInput = (kind: "keydown" | "pointerdown") => (event: Event) => {
const start = event.timeStamp;
requestAnimationFrame(() =>
requestAnimationFrame(() => {
const latency = performance.now() - start;
if (latency >= INPUT_LATENCY_MIN_MS) {
rec.record({ type: "input", kind, latency });
}
}),
);
};
// Capture phase so the timestamp precedes app handlers.
window.addEventListener("keydown", onInput("keydown"), {
capture: true,
passive: true,
});
window.addEventListener("pointerdown", onInput("pointerdown"), {
capture: true,
passive: true,
});
}
function installCensusProbe(
rec: ProfileRecorder,
queryClient: QueryClient,
): void {
const sample = () => {
const observer = getObserverStoreCensus();
rec.record({
type: "census",
observerEvents: observer.observerEvents,
observerAgents: observer.observerAgents,
observerMaxPerAgent: observer.observerMaxPerAgent,
archiveEvents: observer.archiveEvents,
transcripts: observer.transcripts,
queryCache: queryClient.getQueryCache().getAll().length,
domNodes: document.getElementsByTagName("*").length,
});
};
sample();
window.setInterval(sample, CENSUS_INTERVAL_MS);
}
/**
* Start the harness once, wiring all four probes and the JSONL sink. Idempotent
* and non-throwing: profiling must never take down the app it measures.
*/
export function startProfilingHarness(queryClient: QueryClient): void {
if (started) {
return;
}
started = true;
try {
const sid = `session-${Date.now()}`;
const rec = new ProfileRecorder(sid, async (lines) => {
await invoke("append_profiling_log", { fileStem: sid, lines });
});
installIpcProbe(rec);
installRelayProbe(rec);
installStallProbe(rec);
installInputProbe(rec);
installCensusProbe(rec, queryClient);
window.setInterval(() => void rec.flush(), FLUSH_INTERVAL_MS);
window.addEventListener("pagehide", () => void rec.flush());
} catch {
// Never let harness setup break the app being profiled.
}
}
+98
View File
@@ -0,0 +1,98 @@
// Temporary renderer profiling harness (never merges) — ring-buffered recorder.
//
// Records are appended to a bounded in-memory ring buffer and flushed as JSONL
// to a local file (via the `append_profiling_log` Tauri command) every
// `FLUSH_INTERVAL_MS` and on `pagehide`. The buffer is bounded so an unflushed
// or failed sink can never grow the harness into the thing it measures.
import type { ProfileEvent, ProfileRecord } from "@/shared/profiling/types";
/** Max records held between flushes. Oldest are dropped once exceeded. */
export const RING_CAPACITY = 4096;
/** Flush cadence. */
export const FLUSH_INTERVAL_MS = 30_000;
/** Sink receives already-serialized JSONL lines; returns once persisted. */
export type ProfileSink = (lines: string[]) => Promise<void>;
export type RecorderClock = {
now: () => number;
wall: () => number;
};
/**
* Bounded recorder. `record()` stamps the shared envelope and pushes into the
* ring; `flush()` drains the ring through the sink. Drops on overflow are
* counted and surfaced as a synthetic field on the next flush's first line so
* the analyzer can detect (rare) self-pressure.
*/
export class ProfileRecorder {
private readonly buffer: ProfileRecord[] = [];
private droppedSinceFlush = 0;
private flushing = false;
private readonly startedAt: number;
private readonly sid: string;
private readonly sink: ProfileSink;
private readonly clock: RecorderClock;
constructor(
sid: string,
sink: ProfileSink,
clock: RecorderClock = {
now: () => performance.now(),
wall: () => Date.now(),
},
) {
this.sid = sid;
this.sink = sink;
this.clock = clock;
this.startedAt = clock.now();
}
record(event: ProfileEvent): void {
const now = this.clock.now();
const full = {
...event,
t: now,
wall: this.clock.wall(),
sid: this.sid,
up: now - this.startedAt,
} as ProfileRecord;
this.buffer.push(full);
if (this.buffer.length > RING_CAPACITY) {
this.buffer.shift();
this.droppedSinceFlush += 1;
}
}
/** Current buffered record count — used by tests and the pending watchdog. */
size(): number {
return this.buffer.length;
}
async flush(): Promise<void> {
// Serialize flushes; a slow sink must not let two drains race the buffer.
if (this.flushing || this.buffer.length === 0) {
return;
}
this.flushing = true;
const drained = this.buffer.splice(0, this.buffer.length);
const dropped = this.droppedSinceFlush;
this.droppedSinceFlush = 0;
try {
const lines = drained.map((record, index) =>
index === 0 && dropped > 0
? JSON.stringify({ ...record, dropped })
: JSON.stringify(record),
);
await this.sink(lines);
} catch {
// Sink failure must not crash the app being profiled. The dropped count
// is intentionally not restored — the records are already gone.
} finally {
this.flushing = false;
}
}
}
+94
View File
@@ -0,0 +1,94 @@
// Temporary renderer profiling harness (never merges) — record schema.
//
// Every record carries a shared envelope plus a `type` discriminant. One JSONL
// line is written per record; the analyzer keys off `type`.
/** Fields present on every profiling record. */
export type ProfileEnvelope = {
/** `performance.now()` at record time — monotonic, sub-ms, for ordering/deltas. */
t: number;
/** `Date.now()` wall clock — for correlating with Will's felt lag. */
wall: number;
/** Per-launch session id so multiple runs never interleave. */
sid: string;
/** Milliseconds since the harness started this session. */
up: number;
};
export type StallRecord = ProfileEnvelope & {
type: "stall";
/** Observed-minus-expected timer fire, ms (the main-thread block). */
dur: number;
};
export type InputRecord = ProfileEnvelope & {
type: "input";
kind: "keydown" | "pointerdown";
/** Event timestamp → next painted frame, ms. */
latency: number;
};
export type IpcRecord = ProfileEnvelope & {
type: "ipc";
cmd: string;
/** Invoke call → resolve/reject, ms. */
dur: number;
ok: boolean;
};
export type IpcPendingRecord = ProfileEnvelope & {
type: "ipc_pending";
cmd: string;
/** Age of a still-outstanding invoke, ms — the deadlock detector. */
age: number;
};
export type RelayReqRecord = ProfileEnvelope & {
type: "relay_req";
/** RelayClient fetch method name — the REQ→EOSE round-trip label. */
op: string;
/** Method call → resolve (EOSE), ms. */
dur: number;
ok: boolean;
};
export type RelayPubRecord = ProfileEnvelope & {
type: "relay_pub";
/** RelayClient publish method name — the send→ack round-trip label. */
op: string;
/** Method call → resolve (relay OK), ms. */
dur: number;
ok: boolean;
};
export type CensusRecord = ProfileEnvelope & {
type: "census";
/** Total observer events retained across all agents. */
observerEvents: number;
observerAgents: number;
/** Largest single-agent retained event count. */
observerMaxPerAgent: number;
/** Total archived observer events across all channels. */
archiveEvents: number;
transcripts: number;
/** React Query cache entry count. */
queryCache: number;
/** Live DOM node count. */
domNodes: number;
};
export type ProfileRecord =
| StallRecord
| InputRecord
| IpcRecord
| IpcPendingRecord
| RelayReqRecord
| RelayPubRecord
| CensusRecord;
/** Payload the recorder builds internally, before the envelope is stamped. */
export type ProfileEvent = ProfileRecord extends infer R
? R extends ProfileRecord
? Omit<R, keyof ProfileEnvelope>
: never
: never;