The_Great_Archive/trilium
1
0
Fork 0
mirror of https://github.com/zadam/trilium.git synced 2026-09-12 19:50:20 +05:00
Code Issues Actions 18 Packages Projects Releases Wiki Activity

docs(skills): add one for profiling the client

Browse Source 
Two tools, used in order: read a recorded DevTools trace to find which
subsystem is burning the main thread, then instrument that one with
`debug_perf` to measure what it costs. Doing only the second wastes it on
the wrong subsystem.

analyze-trace.mjs replaces the throwaway parsers this otherwise invites,
and carries two format traps that mislead quietly rather than failing:
profiles are numbered per process, so keying on id alone merges the
browser's into the renderer's and blames page code for main-process
frames; and the GPU vsync thread is busy for the whole trace by design,
so "the busiest thread" is never the answer.

The interpretation notes are the part worth having written down. Chief
among them: a stall is the gap between animation frames, so on a
saturated main thread it spans every operation inside one busy period and
two runs cannot be compared by it -- which is how a pair of redraws
landing in one stall reads as a threefold regression.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Elian Doran 2026-08-12 00:05:24 +03:00
parent ecab4dd6ef
commit 8d100e7a62
No known key found for this signature in database
2 changed files with 417 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

139
.claude/skills/profiling-client-performance/SKILL.md Normal file
View File

@ -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 <trace> summary
node ... analyze-trace.mjs <trace> spikes # self time inside the long tasks only — usually the answer
node ... analyze-trace.mjs <trace> profile 25 # top self/total time across the whole trace
node ... analyze-trace.mjs <trace> 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 "<install>/resources/app.asar" | grep <chunk>
# then extract via the node API with path.join("public","src",<chunk>) — 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.

278
.claude/skills/profiling-client-performance/analyze-trace.mjs Executable file
View File

@ -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 <trace> [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 <trace.json|.json.gz> [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;
}