diff --git a/.claude/skills/profiling-client-performance/SKILL.md b/.claude/skills/profiling-client-performance/SKILL.md new file mode 100644 index 0000000000..1f3a79402a --- /dev/null +++ b/.claude/skills/profiling-client-performance/SKILL.md @@ -0,0 +1,139 @@ +--- +name: profiling-client-performance +description: Use when diagnosing a hard client-side performance problem in Trilium — a stutter while typing, janky dragging, a slow widget, a periodic freeze, "why does this only lag on my real database?". Covers reading a recorded Chrome DevTools trace to find which subsystem is burning the main thread, then the in-app `debug_perf` profiler to measure what a specific operation costs. Includes analyze-trace.mjs; don't write a new trace parser or a throwaway timing harness. +--- + +# Profiling the Trilium client + +Two tools, used in order. Skipping the first wastes the second on the wrong subsystem. + +| | reads | answers | needs | +|---|---|---|---| +| `analyze-trace.mjs` | a recorded `.json`/`.json.gz` trace | *which subsystem is burning the main thread* | nothing — works on production builds and traces someone else recorded | +| `debug_perf` | a live session | *what does this specific operation cost, and how often* | source changes + a dev build | + +## 1. Find the subsystem: analyze a trace + +Ask for a DevTools Performance recording (Performance panel → record → download). Then: + +```bash +# A 90MB trace needs the bigger heap; the default one dies parsing it. +node --max-old-space-size=8192 .claude/skills/profiling-client-performance/analyze-trace.mjs summary +node ... analyze-trace.mjs spikes # self time inside the long tasks only — usually the answer +node ... analyze-trace.mjs profile 25 # top self/total time across the whole trace +node ... analyze-trace.mjs timeline # ASCII busy-per-bucket, for spotting a beat +``` + +`spikes` is the one to reach for: a stutter *is* the long tasks, and aggregating self time inside +them with a stack attached names the culprit directly. `summary` prints each long task with the gap +from the previous one — a steady gap means a timer or a debounce, an erratic one means the user is +driving it. + +Two trace-format traps the script already handles, and which will silently mislead a hand-rolled +parser: + +- **Profiles are numbered per process.** Every process starts its `Profile`/`ProfileChunk` ids at + the same value, so keying on `id` alone merges the browser process's profile into the renderer's + and attributes main-process frames to page code. +- **The GPU process's vsync thread is busy for the whole trace by design.** Picking "the busiest + thread" hands you 11.5s of nothing. The renderer main thread is `CrRendererMain`. + +Chunk names in a production trace are hashed (`board-B_DI2aI3.js`). Resolve them by extracting from +the installed app rather than guessing: + +```bash +npx --yes @electron/asar list "/resources/app.asar" | grep +# then extract via the node API with path.join("public","src",) — the CLI mangles the separators +``` + +## 2. Measure the cost: `debug_perf` + +`apps/client/src/services/debug_perf.ts`. **Nothing calls into it by default** — that is deliberate. +Add call sites for as long as the investigation takes, then take them back out. + +```ts +import { perfCount, perfSpan } from "../services/debug_perf"; + +perfCount("board.card.render"); // how often +const end = perfSpan("board.getBoardData"); // how long; end() also returns the ms +try { ... } finally { end(); } +``` + +Adding the first call site is what pulls the module into the bundle, which is also what puts +`triliumPerf` on `window`. There is nothing else to arm. Then, in the devtools console: + +```js +triliumPerf.enable() // also starts reporting stalls +// ...reproduce the problem... +triliumPerf.report() // console.table of calls / total / avg / max +``` + +**Count before you time.** A counter is one line and often reframes the problem outright: "4858 card +renders" divided by 949 cards is *six full redraws*, not the one-per-pointer-move that had been +assumed, which changes what is worth fixing. + +### Reproducing against a real database + +Most of these only appear at real data volumes. Point a dev build at a **copy** of the user's data: + +```powershell +$env:TRILIUM_DATA_DIR = "C:\path\to\a\copy-of-trilium-data" +pnpm desktop:start +``` + +## Interpreting what comes back + +**A STALL line is not the cost of an operation.** It is the gap between animation frames, so on a +saturated main thread it spans *every* operation that fell inside one contiguous busy period. Two +runs are then not comparable — a "regression" from 434ms to 1196ms was two redraws landing in one +stall rather than anything getting slower. For "what did this cost", use a span; only its returned +duration is per-operation. + +**Check for saturation first.** `summary` prints it. Above ~60% busy, stall durations stop meaning +much and the timeline stops having gaps to read. + +**Long Tasks are Chromium-only.** Firefox has no `longtask` entry type, and +`observe({ entryTypes })` drops an unrecognized one with a console warning instead of throwing — so +a naive observer reports nothing at all, which reads as "no stalls happened". `debug_perf` checks +`supportedEntryTypes` and falls back to an animation-frame watchdog, and says which it is using. + +**To separate JavaScript from layout and paint**, close a span in a `useLayoutEffect`: it runs after +Preact has mutated the DOM but before the browser paints. Compare its total against the stall total. +Most of the stall inside the span means JS; most of it outside means layout/paint, and no amount of +memoization will help. + +**Dev-build numbers are inflated but proportionate** — roughly 1.5× against a production Electron +build in practice. Ratios and rankings transfer; absolute figures don't. Firefox's frame-gap +watchdog is coarser than Chromium's Long Tasks, so prefer the desktop app for final numbers. + +## Method + +**Measure before predicting, and say which you are doing.** Predictions from reading code have a +poor record here: "keying the fragment will speed up dragging" (no measurable change), "splitting +the context alone will change nothing" (halved the average stall), "the dragover DOM measuring is +the hot path" (12ms out of 5655ms). Every change that actually moved a number came from a +measurement first. When you must guess, state it as a hypothesis and name the number that would +confirm it. + +**A null result is a result.** Land it if it's a correctness fix, say plainly that it bought +nothing, and put that in the commit message. + +## Patterns that keep showing up + +- **A context change re-renders every consumer, `memo` included.** A component reading a context + that changes often cannot be memoized out of the render path at all. Split volatile state into its + own context first; `memo()` is inert until then. +- **`Intl.*` constructors are ~30× the cost of using the formatter.** Anything constructing one per + row per render is the leaf cost. `apps/client/src/utils/formatters.ts` memoizes on locale + option + set; `formatters.bench.ts` guards it. +- **Change-detection predicates that are broader than they look.** `LoadResults.getNoteIds()` returns + every note in the change set whatever changed about it, so a check meaning "did the title change?" + also fires on every content autosave. +- **Keys belong on the element the `.map()` returns.** A key on a child inside a returned fragment + identifies nothing, and the list reconciles positionally. + +## When done + +Take the call sites out — `grep -rn "perfSpan\|perfCount\|perfLog\|perfTime" apps/client/src` should +return only `debug_perf.ts` itself. Leaving them behind gathers measurements nobody reads. The module +stays; it is the tool, not the measurement. diff --git a/.claude/skills/profiling-client-performance/analyze-trace.mjs b/.claude/skills/profiling-client-performance/analyze-trace.mjs new file mode 100755 index 0000000000..329685cbab --- /dev/null +++ b/.claude/skills/profiling-client-performance/analyze-trace.mjs @@ -0,0 +1,278 @@ +#!/usr/bin/env node +/** + * Analyzes a Chrome DevTools performance trace (Performance panel -> download, `.json` or + * `.json.gz`) recorded from Trilium's client, desktop app included. + * + * Use it to find *which subsystem* is burning the main thread before instrumenting anything. It + * reads a production build just as well as a dev one, which `debug_perf` cannot: no source changes, + * no rebuild, and it works on a trace someone else recorded. + * + * node analyze-trace.mjs [summary|profile|spikes|timeline] [options] + * + * A 90 MB trace needs a bigger heap than the default: + * node --max-old-space-size=8192 analyze-trace.mjs trace.json profile + */ + +import { readFileSync } from "node:fs"; +import { gunzipSync } from "node:zlib"; + +const [ , , tracePath, command = "summary", ...rest ] = process.argv; + +if (!tracePath) { + console.error("usage: analyze-trace.mjs [summary|profile|spikes|timeline]"); + process.exit(1); +} + +const events = loadTrace(tracePath); +const threads = describeThreads(events); +const renderer = pickBusiestRenderer(events, threads); + +switch (command) { + case "summary": summary(); break; + case "profile": profile(numeric(rest, 25)); break; + case "spikes": spikes(numeric(rest, 150)); break; + case "timeline": timeline(numeric(rest, 100)); break; + default: + console.error(`unknown command "${command}"`); + process.exit(1); +} + +function loadTrace(path) { + const raw = readFileSync(path); + const text = path.endsWith(".gz") ? gunzipSync(raw).toString("utf8") : raw.toString("utf8"); + const parsed = JSON.parse(text); + + return Array.isArray(parsed) ? parsed : parsed.traceEvents; +} + +/** Process and thread names, so a pid/tid can be reported as "Renderer / CrRendererMain". */ +function describeThreads(events) { + const processNames = new Map(); + const threadNames = new Map(); + + for (const e of events) { + if (e.name === "process_name") processNames.set(e.pid, e.args?.name); + if (e.name === "thread_name") threadNames.set(`${e.pid}/${e.tid}`, e.args?.name); + } + + return { processNames, threadNames, describe: (pid, tid) => `${processNames.get(pid) ?? "?"} / ${threadNames.get(`${pid}/${tid}`) ?? "?"}` }; +} + +function runTasks(events) { + return events.filter((e) => e.ph === "X" && e.name === "RunTask" && e.dur > 0); +} + +/** + * The renderer's main thread, which is where client work lands. + * + * Picked by busy time among threads named CrRendererMain rather than by raw busy time overall: the + * GPU process's vsync thread is busy for the entire trace by design and would always win. + */ +function pickBusiestRenderer(events, { threadNames }) { + const busy = new Map(); + + for (const task of runTasks(events)) { + const key = `${task.pid}/${task.tid}`; + if (threadNames.get(key) !== "CrRendererMain") continue; + busy.set(key, (busy.get(key) ?? 0) + task.dur); + } + + const [ key ] = [ ...busy.entries() ].sort((a, b) => b[1] - a[1])[0] ?? []; + if (!key) return null; + + const [ pid, tid ] = key.split("/").map(Number); + return { pid, tid, busyUs: busy.get(key) }; +} + +function summary() { + const tasks = runTasks(events); + const start = Math.min(...tasks.map((t) => t.ts)); + const end = Math.max(...tasks.map((t) => t.ts + t.dur)); + + console.log(`trace span: ${((end - start) / 1e6).toFixed(1)}s over ${events.length} events\n`); + + const busy = new Map(); + for (const task of tasks) { + const key = `${task.pid}/${task.tid}`; + busy.set(key, (busy.get(key) ?? 0) + task.dur); + } + + console.log("=== busy time per thread ==="); + for (const [ key, dur ] of [ ...busy.entries() ].sort((a, b) => b[1] - a[1]).slice(0, 8)) { + const [ pid, tid ] = key.split("/").map(Number); + console.log(`${(dur / 1000).toFixed(0).padStart(8)}ms ${threads.describe(pid, tid)}`); + } + + if (!renderer) { + console.log("\nNo CrRendererMain thread found."); + return; + } + + const share = (renderer.busyUs / (end - start)) * 100; + console.log(`\nrenderer main thread ${(renderer.busyUs / 1000).toFixed(0)}ms busy (${share.toFixed(0)}% of the trace)`); + if (share > 60) { + console.log(" Saturated. Individual stall durations conflate whatever fell inside one busy period."); + } + + reportLongTasks(tasks, start); +} + +/** + * Long tasks with the gap from the previous one, which is what exposes a recurring beat: a steady + * gap points at a timer or a debounce, an erratic one at something the user is driving. + */ +function reportLongTasks(tasks, start) { + const long = tasks + .filter((t) => t.pid === renderer.pid && t.tid === renderer.tid && t.dur > 50000) + .sort((a, b) => a.ts - b.ts); + + console.log(`\n=== ${long.length} tasks over 50ms ===`); + long.slice(0, 40).forEach((task, index) => { + const gap = index ? `${((task.ts - long[index - 1].ts) / 1000).toFixed(0)}ms` : "-"; + console.log(` @${((task.ts - start) / 1000).toFixed(0).padStart(7)}ms ${(task.dur / 1000).toFixed(0).padStart(5)}ms gap ${gap}`); + }); +} + +/** + * Reconstructs the renderer's V8 sampling profile from its Profile/ProfileChunk events. + * + * Keyed on pid *and* id: every process numbers its profiles from the same sequence, so keying on id + * alone silently merges the browser process's profile into the renderer's and attributes main-process + * frames to page code. + */ +function buildProfile(pid) { + const profile = { nodes: new Map(), samples: [], deltas: [], startTime: 0 }; + + for (const e of events) { + if (e.pid !== pid) continue; + + if (e.name === "Profile" && e.args?.data) { + profile.startTime = e.args.data.startTime; + } else if (e.name === "ProfileChunk" && e.args?.data) { + const cpuProfile = e.args.data.cpuProfile ?? {}; + for (const node of cpuProfile.nodes ?? []) profile.nodes.set(node.id, node); + profile.samples.push(...(cpuProfile.samples ?? [])); + profile.deltas.push(...(e.args.data.timeDeltas ?? [])); + } + } + + const parents = new Map(); + for (const [ id, node ] of profile.nodes) { + if (node.parent != null) parents.set(id, node.parent); + for (const child of node.children ?? []) if (!parents.has(child)) parents.set(child, id); + } + + const label = (id) => { + const frame = profile.nodes.get(id)?.callFrame; + if (!frame) return "?"; + return `${frame.functionName || "(anon)"} @ ${(frame.url ?? "").split("/").pop()}:${frame.lineNumber + 1}`; + }; + + return { ...profile, parents, label, stackOf: (id) => { + const stack = []; + for (let cur = id, guard = 0; cur != null && guard < 60; cur = parents.get(cur), guard++) stack.push(label(cur)); + return stack; + } }; +} + +/** Walks the profile once, yielding [timestampUs, nodeId, durationUs] per sample. */ +function* walkSamples(profile) { + let ts = profile.startTime; + for (let i = 0; i < profile.samples.length; i++) { + ts += profile.deltas[i] ?? 0; + yield [ ts, profile.samples[i], profile.deltas[i] ?? 0 ]; + } +} + +function profile(topN) { + const profile = buildProfile(renderer.pid); + if (!profile.samples.length) { + console.log("No CPU profile in this trace. Record with the Performance panel's default settings."); + return; + } + + console.log(`renderer profile: ${profile.samples.length} samples, ${profile.nodes.size} nodes\n`); + + const self = new Map(); + for (const [ , id, dur ] of walkSamples(profile)) self.set(id, (self.get(id) ?? 0) + dur); + + const ranked = [ ...self.entries() ].sort((a, b) => b[1] - a[1]); + + console.log("=== self time (where the CPU actually was) ==="); + for (const [ id, dur ] of ranked.slice(0, topN)) { + console.log(`${(dur / 1000).toFixed(1).padStart(9)}ms ${profile.label(id)}`); + } + + // Total time folds each sample into every distinct frame above it, so a dispatcher that is never + // itself on-CPU still shows the cost of everything it calls. + const total = new Map(); + for (const [ id, dur ] of self) { + for (const frame of new Set(profile.stackOf(id))) total.set(frame, (total.get(frame) ?? 0) + dur); + } + + console.log("\n=== total time (self plus everything called) ==="); + for (const [ frame, dur ] of [ ...total.entries() ].sort((a, b) => b[1] - a[1]).slice(0, topN)) { + console.log(`${(dur / 1000).toFixed(1).padStart(9)}ms ${frame}`); + } + + console.log("\n=== stacks of the heaviest frames ==="); + for (const [ id, dur ] of ranked.slice(0, 5)) { + console.log(`\n ${(dur / 1000).toFixed(1)}ms self`); + for (const frame of profile.stackOf(id).slice(0, 18)) console.log(` ${frame}`); + } +} + +/** Aggregates self time inside the long tasks only, which is what a stutter is made of. */ +function spikes(thresholdMs) { + const profile = buildProfile(renderer.pid); + const tasks = runTasks(events) + .filter((t) => t.pid === renderer.pid && t.tid === renderer.tid && t.dur > thresholdMs * 1000); + + if (!tasks.length) { + console.log(`No tasks over ${thresholdMs}ms on the renderer main thread.`); + return; + } + + const inside = (ts) => tasks.some((t) => ts >= t.ts && ts <= t.ts + t.dur); + const self = new Map(); + const stacks = new Map(); + let sampled = 0; + + for (const [ ts, id, dur ] of walkSamples(profile)) { + if (!inside(ts)) continue; + sampled += dur; + const frame = profile.label(id); + self.set(frame, (self.get(frame) ?? 0) + dur); + if (!stacks.has(frame)) stacks.set(frame, profile.stackOf(id)); + } + + console.log(`=== inside ${tasks.length} tasks over ${thresholdMs}ms (${(sampled / 1000).toFixed(0)}ms sampled) ===`); + for (const [ frame, dur ] of [ ...self.entries() ].sort((a, b) => b[1] - a[1]).slice(0, 15)) { + console.log(`\n${(dur / 1000).toFixed(1)}ms ${frame}`); + for (const parent of stacks.get(frame).slice(1, 12)) console.log(` ${parent}`); + } +} + +function timeline(bucketMs) { + const tasks = runTasks(events).filter((t) => t.pid === renderer.pid && t.tid === renderer.tid); + const start = Math.min(...tasks.map((t) => t.ts)); + const bucketUs = bucketMs * 1000; + const buckets = new Map(); + + for (const task of tasks) { + const bucket = Math.floor((task.ts - start) / bucketUs); + buckets.set(bucket, (buckets.get(bucket) ?? 0) + task.dur); + } + + console.log(`=== renderer main thread, ${bucketMs}ms buckets (one # = ${(bucketMs / 30).toFixed(1)}ms busy) ===`); + for (let i = 0; i <= Math.max(...buckets.keys()); i++) { + const ms = (buckets.get(i) ?? 0) / 1000; + const bar = "#".repeat(Math.min(60, Math.round(ms / (bucketMs / 30)))); + console.log(`${((i * bucketMs) / 1000).toFixed(1).padStart(7)}s ${String(Math.round(ms)).padStart(4)}ms ${bar}`); + } +} + +function numeric(args, fallback) { + const value = Number(args[0]); + return Number.isFinite(value) ? value : fallback; +}