Performance trace, load test and chapter read-ahead
A switchable trace (DATA/perf/trace.on or PERF_TRACE=1) records every request's phases (stat, open, first read, disk vs network wait), browser resource timings, page-turn waits and flow stalls, a cold storage probe, event-loop lag, scans and scraper calls as JSONL. tools/perf-report.js says which phase slow loads spend their time in; tools/perf-bench.js simulates readers. READ_AHEAD (default on) reads an opened chapter's pages, then the next chapter's, into the OS cache so a NAS's cold reads stop reaching the browser. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
MaashkinoozheandClaude Opus 5.5 committed
1 parent
ea8a5b40e7
commit
896726a51b
16 files changed
+893
-8
No files matched your search
@@ -0,0 +1,196 @@
|
||||
#!/usr/bin/env node
|
||||
'use strict';
|
||||
/*
|
||||
* Summarise a performance trace (docs/performance.md) and say where slow page loads spend their time.
|
||||
*
|
||||
* node tools/perf-report.js DATA/perf all trace files in the folder
|
||||
* node tools/perf-report.js trace-2026-10-29.jsonl --since 2026-10-29T18:00 --until … --slow 500 --json
|
||||
*
|
||||
* Plain text by default (readable by people and agents); --json prints the numbers only.
|
||||
*/
|
||||
const fs = require('fs'), path = require('path');
|
||||
|
||||
function parseArgs(argv) {
|
||||
const opts = { files: [], since: null, until: null, slow: 500, json: false };
|
||||
for (let i = 0; i < argv.length; i++) {
|
||||
const a = argv[i];
|
||||
if (a === '--since') opts.since = Date.parse(argv[++i]);
|
||||
else if (a === '--until') opts.until = Date.parse(argv[++i]);
|
||||
else if (a === '--slow') opts.slow = +argv[++i];
|
||||
else if (a === '--json') opts.json = true;
|
||||
else if (a === '-h' || a === '--help') opts.help = true;
|
||||
else opts.files.push(a);
|
||||
}
|
||||
return opts;
|
||||
}
|
||||
|
||||
function readEvents(inputs, { since, until }) {
|
||||
const files = inputs.flatMap(p => fs.statSync(p).isDirectory()
|
||||
? fs.readdirSync(p).filter(n => /^trace-.*\.jsonl$/.test(n)).sort().map(n => path.join(p, n)) : [p]);
|
||||
const events = [];
|
||||
for (const file of files) for (const line of fs.readFileSync(file, 'utf8').split('\n')) {
|
||||
if (!line) continue;
|
||||
let e; try { e = JSON.parse(line); } catch { continue; }
|
||||
if ((since && e.t < since) || (until && e.t > until)) continue;
|
||||
events.push(e);
|
||||
}
|
||||
return events.sort((a, b) => a.t - b.t);
|
||||
}
|
||||
|
||||
const pct = (values, p) => {
|
||||
const v = values.filter(x => typeof x === 'number').sort((a, b) => a - b);
|
||||
if (!v.length) return null;
|
||||
return v[Math.min(v.length - 1, Math.floor((p / 100) * v.length))];
|
||||
};
|
||||
const stats = values => {
|
||||
const v = values.filter(x => typeof x === 'number');
|
||||
return v.length ? { n: v.length, p50: pct(v, 50), p90: pct(v, 90), p99: pct(v, 99), max: Math.max(...v) } : { n: 0 };
|
||||
};
|
||||
const isPageImage = e => e.k === 'req' && e.path.startsWith('/lib/') && e.path.split('/').length >= 6;
|
||||
|
||||
// Where one served image spent its time on the server.
|
||||
function serverPhases(e) {
|
||||
const stat = e.stat ?? 0, open = e.open != null ? e.open - stat : 0, firstRead = e.first != null && e.open != null ? e.first - e.open : 0;
|
||||
const rest = Math.max(0, (e.disk ?? 0) - firstRead), net = e.netWait ?? 0;
|
||||
const tail = e.readEnd != null ? Math.max(0, e.ms - e.readEnd) : 0;
|
||||
return { stat, open, firstRead, readRest: rest, netWait: net, tail };
|
||||
}
|
||||
const dominant = phases => Object.entries(phases).sort((a, b) => b[1] - a[1])[0][0];
|
||||
|
||||
function analyse(events, { slow }) {
|
||||
const out = { window: events.length ? { from: new Date(events[0].t).toISOString(), to: new Date(events.at(-1).t).toISOString() } : null };
|
||||
const reqs = events.filter(e => e.k === 'req');
|
||||
const imgs = reqs.filter(isPageImage), served = imgs.filter(e => e.status === 200 && !e.aborted);
|
||||
out.requests = { total: reqs.length, pageImages: imgs.length, served: served.length,
|
||||
notModified: imgs.filter(e => e.status === 304).length, aborted: imgs.filter(e => e.aborted).length,
|
||||
errors: imgs.filter(e => e.status >= 400).length, keepAliveReuse: imgs.length ? round(imgs.filter(e => e.conn > 1).length / imgs.length) : null };
|
||||
out.serverImage = { total: stats(served.map(e => e.ms)), stat: stats(served.map(e => e.stat)),
|
||||
firstRead: stats(served.map(e => serverPhases(e).firstRead)), disk: stats(served.map(e => e.disk)),
|
||||
netWait: stats(served.map(e => e.netWait)), kbytes: stats(served.map(e => e.bytes / 1024)) };
|
||||
const slowServed = served.filter(e => e.ms >= slow);
|
||||
out.slowServer = { count: slowServed.length, share: served.length ? round(slowServed.length / served.length) : null, by: {} };
|
||||
for (const e of slowServed) { const d = dominant(serverPhases(e)); out.slowServer.by[d] = (out.slowServer.by[d] || 0) + 1; }
|
||||
out.slowServer.worst = slowServed.sort((a, b) => b.ms - a.ms).slice(0, 10)
|
||||
.map(e => ({ at: new Date(e.t).toISOString(), ms: e.ms, ...serverPhases(e), path: e.path }));
|
||||
|
||||
const api = {};
|
||||
for (const e of reqs.filter(e => e.path.startsWith('/api/'))) (api[e.path] ||= []).push(e.ms);
|
||||
out.api = Object.fromEntries(Object.entries(api).map(([p, v]) => [p, stats(v)]).sort((a, b) => (b[1].p99 || 0) - (a[1].p99 || 0)).slice(0, 12));
|
||||
|
||||
// Browser view, matched to the server's record of the same file where possible.
|
||||
const res = events.filter(e => e.k === 'client' && e.e === 'res'), byPath = new Map();
|
||||
const decoded = p => { try { return decodeURIComponent(p); } catch { return p; } };
|
||||
for (const e of imgs) { const key = decoded(e.path); (byPath.get(key) || byPath.set(key, []).get(key)).push(e); }
|
||||
const matched = res.map(r => {
|
||||
const cands = (byPath.get(r.url) || []).filter(s => s.t <= r.t + 1000 && s.t >= r.t - 120000);
|
||||
const s = cands.at(-1);
|
||||
return { ...r, serverMs: s ? s.ms : null };
|
||||
});
|
||||
const loaded = matched.filter(r => !r.cached);
|
||||
out.browserImage = { total: stats(loaded.map(r => r.total)), queue: stats(loaded.map(r => r.queue)),
|
||||
ttfb: stats(loaded.map(r => r.ttfb)), download: stats(loaded.map(r => r.download)),
|
||||
connect: stats(loaded.map(r => r.connect)), dns: stats(loaded.map(r => r.dns)), fromCache: matched.length - loaded.length };
|
||||
const slowBrowser = loaded.filter(r => r.total >= slow);
|
||||
out.slowBrowser = { count: slowBrowser.length, share: loaded.length ? round(slowBrowser.length / loaded.length) : null, by: {} };
|
||||
for (const r of slowBrowser) {
|
||||
const parts = { server: r.serverMs ?? 0, network: Math.max(0, (r.ttfb ?? 0) + (r.download ?? 0) - (r.serverMs ?? 0)),
|
||||
queue: r.queue ?? 0, connect: (r.connect ?? 0) + (r.dns ?? 0) };
|
||||
const d = r.serverMs == null ? 'unmatched' : dominant(parts);
|
||||
out.slowBrowser.by[d] = (out.slowBrowser.by[d] || 0) + 1;
|
||||
}
|
||||
const views = events.filter(e => e.k === 'client' && e.e === 'view'), stalls = events.filter(e => e.k === 'client' && e.e === 'stall');
|
||||
out.pageTurns = { count: views.length, preloaded: views.filter(v => v.preloaded).length, wait: stats(views.map(v => v.wait)),
|
||||
over300ms: views.filter(v => v.wait >= 300).length, over1s: views.filter(v => v.wait >= 1000).length };
|
||||
out.flowStalls = { count: stalls.length, wait: stats(stalls.map(s => s.wait)), over1s: stalls.filter(s => s.wait >= 1000).length };
|
||||
out.clients = [...new Set(events.filter(e => e.k === 'client' && e.e === 'hello').map(e => `${e.user}: ${e.ua}`))].slice(0, 10);
|
||||
|
||||
// Storage probe: cold reads of random pages; a long read after quiet time points at disks waking up.
|
||||
const nas = events.filter(e => e.k === 'nas' && !e.error);
|
||||
let lastIo = null;
|
||||
const ioTimes = events.filter(e => isPageImage(e) || e.k === 'nas' || e.k === 'ahead').map(e => e.t);
|
||||
out.nas = { probes: nas.length, errors: events.filter(e => e.k === 'nas' && e.error).length, first: stats(nas.map(e => e.firstMs)), total: stats(nas.map(e => e.ms)) };
|
||||
out.nas.slow = nas.filter(e => e.firstMs >= 1000).map(e => {
|
||||
let i = ioTimes.findIndex(t => t >= e.t); lastIo = i > 0 ? ioTimes[i - 1] : null;
|
||||
return { at: new Date(e.t).toISOString(), firstMs: e.firstMs, quietMinBefore: lastIo ? round((e.t - e.ms - lastIo) / 60000) : null };
|
||||
}).slice(0, 30);
|
||||
|
||||
const loops = events.filter(e => e.k === 'loop');
|
||||
out.eventLoop = { samples: loops.length, lagP99: stats(loops.map(e => e.lagP99)), lagMax: stats(loops.map(e => e.lagMax)), cpu: stats(loops.map(e => e.cpu)), rssMB: stats(loops.map(e => e.rss)) };
|
||||
|
||||
const scans = events.filter(e => e.k === 'scan');
|
||||
out.scans = { count: scans.length, ms: stats(scans.map(e => e.ms)) };
|
||||
const during = e => scans.some(s => e.t >= s.t - s.ms && e.t - e.ms <= s.t);
|
||||
out.scans.slowImagesDuringScan = slowServed.filter(during).length;
|
||||
const span = events.length ? events.at(-1).t - events[0].t : 0;
|
||||
out.scans.timeShare = span ? round(scans.reduce((a, s) => a + s.ms, 0) / span) : null;
|
||||
|
||||
const ahead = events.filter(e => e.k === 'ahead');
|
||||
out.readAhead = { batches: ahead.length, replaced: ahead.filter(e => e.replaced).length, files: ahead.reduce((a, e) => a + e.done, 0),
|
||||
MBps: stats(ahead.filter(e => e.ms > 0 && e.bytes > 0).map(e => round(e.bytes / 1048.576 / e.ms))) };
|
||||
const scraper = events.filter(e => e.k === 'scraper');
|
||||
out.scraper = { calls: scraper.length, errors: scraper.filter(e => e.error).length, ms: stats(scraper.map(e => e.ms)) };
|
||||
out.verdict = verdict(out, slow);
|
||||
return out;
|
||||
}
|
||||
|
||||
function verdict(o, slow) {
|
||||
const lines = [];
|
||||
const top = by => Object.entries(by).sort((a, b) => b[1] - a[1]);
|
||||
if (o.slowServer.count) {
|
||||
const [[phase, n]] = top(o.slowServer.by);
|
||||
const name = { stat: 'the file lookup (stat) on the storage', open: 'opening the file', firstRead: 'the first read from storage',
|
||||
readRest: 'reading the rest of the file from storage', netWait: 'the client receiving data (network)', tail: 'flushing to the client' }[phase];
|
||||
lines.push(`${o.slowServer.count} of ${o.serverImage.total.n} served pages took >= ${slow} ms on the server; ${n} of them mostly in ${name}.`);
|
||||
} else if (o.serverImage.total.n) lines.push(`No served page took >= ${slow} ms on the server (p99 ${o.serverImage.total.p99} ms).`);
|
||||
if (o.slowBrowser.count) {
|
||||
const [[part, n]] = top(o.slowBrowser.by);
|
||||
lines.push(`${o.slowBrowser.count} of ${o.browserImage.total.n} page loads took >= ${slow} ms in the browser; mostly ${part} (${n}).`);
|
||||
}
|
||||
if (o.pageTurns.count) lines.push(`Page turns: ${o.pageTurns.preloaded}/${o.pageTurns.count} preloaded, ${o.pageTurns.over300ms} waited >= 300 ms, ${o.pageTurns.over1s} >= 1 s (p90 ${o.pageTurns.wait.p90 ?? 0} ms).`);
|
||||
if (o.flowStalls.count) lines.push(`Flow mode: ${o.flowStalls.count} pages were on screen before their image (p90 ${o.flowStalls.wait.p90} ms, ${o.flowStalls.over1s} >= 1 s).`);
|
||||
if (o.nas.probes) {
|
||||
lines.push(`Storage probe (cold page): first byte p50 ${o.nas.first.p50} ms, p99 ${o.nas.first.p99} ms, max ${o.nas.first.max} ms; ${o.nas.slow.length} probes >= 1 s.`);
|
||||
const sleepy = o.nas.slow.filter(s => s.quietMinBefore >= 5).length;
|
||||
if (sleepy) lines.push(`${sleepy} slow probes followed >= 5 min without library reads: disks waking from standby is likely.`);
|
||||
}
|
||||
if (o.eventLoop.samples && (o.eventLoop.lagMax.max || 0) >= 200) lines.push(`Event loop blocked up to ${o.eventLoop.lagMax.max} ms (reader CPU work holds requests back).`);
|
||||
if (o.scans.slowImagesDuringScan) lines.push(`${o.scans.slowImagesDuringScan} slow pages overlapped a library scan (scans ran ${Math.round((o.scans.timeShare || 0) * 100)}% of the time).`);
|
||||
return lines;
|
||||
}
|
||||
|
||||
function print(o) {
|
||||
const s = x => (x && x.n ? `n=${x.n} p50=${x.p50} p90=${x.p90} p99=${x.p99} max=${x.max}` : 'n=0');
|
||||
const out = [];
|
||||
out.push(`Trace ${o.window ? `${o.window.from} .. ${o.window.to}` : '(empty)'}`, '', 'Verdict:', ...o.verdict.map(l => ' - ' + l), '');
|
||||
out.push('Requests', ` ${JSON.stringify(o.requests)}`);
|
||||
out.push('Server, page images (ms)');
|
||||
for (const k of ['total', 'stat', 'firstRead', 'disk', 'netWait', 'kbytes']) out.push(` ${k.padEnd(10)} ${s(o.serverImage[k])}`);
|
||||
out.push(` slow by phase ${JSON.stringify(o.slowServer.by)}`);
|
||||
for (const w of o.slowServer.worst) out.push(` ${w.at} ${w.ms} ms stat=${w.stat} first=${w.firstRead} rest=${w.readRest} net=${w.netWait} ${w.path}`);
|
||||
out.push('Browser, page images (ms)');
|
||||
for (const k of ['total', 'queue', 'ttfb', 'download', 'connect', 'dns']) out.push(` ${k.padEnd(10)} ${s(o.browserImage[k])}`);
|
||||
out.push(` from browser cache ${o.browserImage.fromCache}; slow by part ${JSON.stringify(o.slowBrowser.by)}`);
|
||||
out.push(`Page turns ${o.pageTurns.count} (${o.pageTurns.preloaded} preloaded) wait ${s(o.pageTurns.wait)}`);
|
||||
out.push(`Flow stalls ${o.flowStalls.count} wait ${s(o.flowStalls.wait)}`);
|
||||
out.push(`Storage probe first byte ${s(o.nas.first)} total ${s(o.nas.total)} errors ${o.nas.errors}`);
|
||||
for (const p of o.nas.slow) out.push(` ${p.at} first=${p.firstMs} ms after ${p.quietMinBefore ?? '?'} min quiet`);
|
||||
out.push(`Event loop lagP99 ${s(o.eventLoop.lagP99)} lagMax ${s(o.eventLoop.lagMax)} cpu% ${s(o.eventLoop.cpu)} rssMB ${s(o.eventLoop.rssMB)}`);
|
||||
out.push(`Scans ${o.scans.count} ${s(o.scans.ms)}`);
|
||||
out.push(`Read-ahead ${JSON.stringify(o.readAhead)}`);
|
||||
out.push(`Scraper calls ${o.scraper.calls} errors ${o.scraper.errors} ${s(o.scraper.ms)}`);
|
||||
out.push('API (ms, slowest p99 first)');
|
||||
for (const [p, v] of Object.entries(o.api)) out.push(` ${p.padEnd(28)} ${s(v)}`);
|
||||
if (o.clients.length) out.push('Clients', ...o.clients.map(c => ' ' + c));
|
||||
return out.join('\n');
|
||||
}
|
||||
|
||||
const round = v => Math.round(v * 100) / 100;
|
||||
|
||||
if (require.main === module) {
|
||||
const opts = parseArgs(process.argv.slice(2));
|
||||
if (opts.help || !opts.files.length) { console.log('usage: node tools/perf-report.js <trace.jsonl|folder>... [--since ISO] [--until ISO] [--slow ms] [--json]'); process.exit(opts.help ? 0 : 2); }
|
||||
const result = analyse(readEvents(opts.files, opts), opts);
|
||||
console.log(opts.json ? JSON.stringify(result, null, 2) : print(result));
|
||||
}
|
||||
|
||||
module.exports = { analyse, readEvents, print };
|
||||
Reference in new issue
Block a user