diff --git a/.dockerignore b/.dockerignore index 09c8786..5de4c11 100644 --- a/.dockerignore +++ b/.dockerignore @@ -23,6 +23,8 @@ !scraper/** !peering/ !peering/** +!perf/ +!perf/** !tools/ !tools/** scraper/.cache/** diff --git a/AGENTS.md b/AGENTS.md index a138ee7..2bc9722 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -12,6 +12,7 @@ Guide for contributors and coding agents. Users who only want to run it: [docs/d | `scraper/` | Download queue daemon (`service.js`, `daemon.js`), source adapters and parsers, the publisher that writes the library, metadata lookups | | `peering/` | Optional server-to-server sharing (gateway, client, adapter) | | `runtime/` | In-container supervisor and configuration | +| `perf/` | Switchable performance trace and chapter read-ahead ([docs/performance.md](docs/performance.md)) | | `discovery/`, `greatest/` | Discovery Scout and the Greatest of All Time dashboard | | `tools/` | Demo library, health checks, maintenance tools (dry run by default), UI and Compose test drivers | | `deploy/` | `circus.sh` operations helper, HTTPS with Caddy | diff --git a/Dockerfile b/Dockerfile index 33a0451..656cfc4 100644 --- a/Dockerfile +++ b/Dockerfile @@ -11,6 +11,7 @@ COPY tools ./tools COPY scraper ./scraper COPY peering ./peering COPY runtime ./runtime +COPY perf ./perf RUN mkdir -p /library /data && chown node:node /data /library ENV PORT=8080 LIBRARY=/library DATA=/data TZ=UTC EXPOSE 8080 diff --git a/README.md b/README.md index 2b5273e..a1d9700 100644 --- a/README.md +++ b/README.md @@ -63,6 +63,8 @@ you put in `.env` are listed in [docs/deployment.md](docs/deployment.md#4-config | `SIGNUP` | `closed` | `open` lets anyone create an account. Otherwise the admin adds users under Settings | | `SCAN_INTERVAL` | `10` | Minutes between shallow library change checks (`0` disables this timer) | | `FULL_SCAN_INTERVAL` | `1440` | Minutes between full library reconciliations (`0` disables this timer) | +| `READ_AHEAD` | `1` | Read an opened chapter's pages (then the next chapter's) into the OS cache ahead of the browser; `0` = off ([docs/performance.md](docs/performance.md)) | +| `PERF_TRACE` | `0` | `1` = performance trace from the start; it can also be switched at runtime with the file `DATA/perf/trace.on` ([docs/performance.md](docs/performance.md)) | | `SCAN_CONCURRENCY` | `8` | Chapter folders and images probed at once by an uncached scan (1–64); higher helps on network storage | | `COOKIE_SECURE` | – | `1` marks the login cookie `Secure` (use it when you serve over HTTPS) | | `SCRAPER_URL` | `http://127.0.0.1:8091` | Private scraper daemon URL | diff --git a/docs/architecture.md b/docs/architecture.md index 7297d1e..3676450 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -210,6 +210,7 @@ All requests and responses are JSON. POSTs require `Content-Type: application/js | `POST /api/moments` `{m, c, v, pages, layout, region, cat, note}` | user | Save a moment: `pages` are 1–4 distinct indexes in displayed order, `layout` `row` (default) or `column`, `cat` one of `twist hot awesome cute funny feels` (required), `region` fractions of the pages put together, or null | | `POST /api/moments/update` `{id, cat?, region?, note?}` · `POST /api/moments/delete` `{id}` | user | Edit or delete one of the caller's own moments (another user's id is `404`) | | `GET /api/notifications` · `POST /api/notifications/read` `{id \| all}` | user | Notification list and read state | +| `POST /api/perf` `{page, events: […]}` | user | Browser timings for the performance trace; ignored with `{on: false}` while the trace is off. `/api/chapter` returns `perf: true` while it is on ([performance.md](performance.md)) | | `GET /api/admin` | admin | Users, last scan result, library path | | `POST /api/admin/rescan` `{full}` | admin | Scan now, and wait for the result | | `POST /api/admin/user` `{name, password, admin}` | admin | Create a user or reset a password | @@ -400,6 +401,7 @@ docker compose up -d --build | User data | `db.json` is rewritten as a whole, at most about twice per second while people read. Comfortable up to a few MB (a household or small group, thousands of chapters read) | | Concurrency | One process, one writer. No clustering or horizontal scaling by design | | Images | Served as stored. No resizing or thumbnails, so large covers make the library page heavy | +| Slow storage | Opening a chapter reads its pages (then the next chapter's) into the OS cache, two at a time (`READ_AHEAD`). Where the time goes: [performance.md](performance.md) | ## 10. Design decisions diff --git a/docs/performance.md b/docs/performance.md new file mode 100644 index 0000000..370d2c0 --- /dev/null +++ b/docs/performance.md @@ -0,0 +1,78 @@ +# Performance trace, load test and read-ahead + +When pages load slowly, the trace shows where the time goes: the storage (a NAS, a disk waking up), the +reader process (CPU, event loop), library scans running at the same time, or the network to the browser. + +## Switching the trace on and off + +No restart is needed. The reader checks for a flag file every 5 seconds: + +```bash +touch "$DATA/perf/trace.on" # on (Docker: the data folder mounted at /data) +rm "$DATA/perf/trace.on" # off +``` + +`PERF_TRACE=1` in the environment keeps it on from the start. While it is off, the reader does no extra work. + +The trace goes to `DATA/perf/trace-YYYY-MM-DD.jsonl` (UTC days), one JSON object per line. Files older than +14 days are deleted; one day stops growing at 256 MB. The file contains request paths (manga and chapter +names) and user names, so treat it like the rest of `DATA`. + +## What is recorded + +Every line has `t` (server time, ms since the epoch) and `k` (kind): + +| `k` | Fields | Meaning | +|---|---|---| +| `req` | `m`, `path`, `status`, `ms`, `bytes`, `conn`, `aborted`; for files `stat`, `open`, `first`, `readEnd`, `disk`, `netWait`; for pages also `access` | One HTTP request. Phase fields are ms since the request arrived: `stat` file lookup done, `open` file opened, `first` first chunk read, `readEnd` last chunk read. `disk` = time spent waiting for the storage, `netWait` = time the file stream was paused because the client did not take data fast enough. `conn` > 1 means a reused keep-alive connection | +| `client` | `e`: `hello`, `res`, `view`, `stall` | Reported by the reader page while the trace is on (`public/perf.js`). `res`: the browser's resource timing of a page image (`queue`, `dns`, `connect`, `ttfb`, `download`, `total`, `size`, `server` = the reader's `stat` time, `cached`). `view`: a page turn in page/book mode, `wait` until the new page was decoded and painted, `preloaded`. `stall`: flow mode, a page on screen before its image, `wait` until it loaded. `hello`: browser, viewport, connection type | +| `nas` | `statMs`, `firstMs`, `ms`, `bytes` or `error` | Every `PERF_NAS_PROBE_SECONDS` (60) one random library page is read. Out of a large library it is almost never cached, so this is the storage's cold latency over time; seconds after a quiet period mean disks were in standby | +| `loop` | `lagP50`, `lagP99`, `lagMax`, `cpu`, `rss`, `heap` | Every 5 s: event-loop delay (ms), CPU % of one core, memory (MB) | +| `scan` | `mode`, `ms`, `changed` | Library scans (change checks every `SCAN_INTERVAL`, full reconciliations) | +| `ahead` | `tag`, `files`, `done`, `skipped`, `bytes`, `ms`, `replaced` | A read-ahead batch (below) | +| `scraper` | `endpoint`, `ms`, `status`/`error` | Calls from the reader to the scraper daemon | +| `trace` | `on` | The trace was switched on or off | + +## Reading the result + +```bash +node tools/perf-report.js "$DATA/perf" # all days +node tools/perf-report.js "$DATA/perf" --since 2026-10-29T18:00Z --slow 300 +docker compose exec reader node tools/perf-report.js /data/perf # inside the container +``` + +The report starts with a verdict (which phase dominates the slow loads), then percentiles for the server's +phases, the browser's timings, page turns, flow stalls, the storage probe, the event loop, scans, read-ahead +and the API routes. `--json` prints the same numbers for scripts and agents. + +How to read it: + +- **Slow `firstRead` / `readRest`, slow `nas` probes**: the storage is slow. Probes of several seconds after + minutes without reads point at disk standby (on a Synology: *Control Panel → Hardware & Power → HDD + Hibernation*). +- **Slow `stat`**: metadata lookups on the storage are slow (often during a scan, see `scan`). +- **High `netWait`, or browser `download` much longer than the server's `ms`**: the network between server + and browser (Wi-Fi, VPN, a proxy). +- **Browser `queue`**: the browser waited for a free connection (too many parallel requests). +- **High `lagMax`**: the reader process was busy and could not answer. + +## Load test + +`tools/perf-bench.js` simulates readers paging through random chapters with a think time and a small +look-ahead, and reports how long a reader looked at an empty page (`wait`), time to first byte and total +per page. It only reads (no progress is written). Use a separate account: + +```bash +BENCH_PASSWORD=… node tools/perf-bench.js --url http://server:8080 --user bench --password-env BENCH_PASSWORD \ + --readers 4 --chapters 3 --pages 40 --think 400 --ahead 2 +``` + +Run it with the trace on to see the server's side of the same requests. + +## Read-ahead + +`READ_AHEAD=1` (default): when a chapter is opened, the reader reads its pages once in page order, starting +at the saved page, two at a time, and then the next chapter's. The data is thrown away; the OS page cache +keeps it, so the browser's requests are answered from memory instead of the storage. Opening another +chapter replaces whatever is still queued. `READ_AHEAD=0` turns it off (useful on a local SSD, or to compare +with the trace). diff --git a/perf/read-ahead.js b/perf/read-ahead.js new file mode 100644 index 0000000..6caa2e7 --- /dev/null +++ b/perf/read-ahead.js @@ -0,0 +1,75 @@ +'use strict'; +/* + * Read-ahead for network libraries: when a chapter is opened, its pages (then the next chapter's) are read + * once in page order, a few at a time, so the OS page cache holds them before the browser asks. On a NAS + * with spinning disks a cold page costs 10-100 ms (seconds while a disk wakes up); a cached one well under + * 5 ms. The data is discarded; only the cache effect matters. + * + * Only the newest chapter request counts: opening another chapter replaces whatever is still queued. + */ +const fs = require('fs'); + +class ReadAhead { + constructor({ concurrency = 2, remember = 4000, onBatch = () => {} } = {}) { + this.concurrency = concurrency; this.remember = remember; this.onBatch = onBatch; + this.queue = []; this.active = 0; this.recent = new Map(); this.batch = null; this.buffers = []; + } + + // `files` in reading order; `tag` names the batch in the trace. + warm(files, tag) { + const fresh = files.filter(f => !this.recent.has(f)); + if (this.batch) this.finishBatch(true); + this.queue = fresh; + this.batch = { tag, files: fresh.length, skipped: files.length - fresh.length, bytes: 0, t0: performance.now(), done: 0 }; + if (!fresh.length) this.finishBatch(false); + this.pump(); + } + // Runs after the current batch (e.g. the next chapter) unless a newer warm() replaces it first. + then(files, tag) { + const after = () => this.warm(files, tag); + if (!this.batch) after(); else this.batch.next = after; + } + + pump() { + while (this.active < this.concurrency && this.queue.length) { + const file = this.queue.shift(), batch = this.batch; + this.active++; + this.readFile(file).then(bytes => { + this.note(file); + if (batch === this.batch) { batch.bytes += bytes; batch.done++; } + }, () => {}).finally(() => { + this.active--; + // A replaced batch's reads may still be running; the current batch ends when all reads have. + if (this.batch && !this.queue.length && !this.active) this.finishBatch(false); + this.pump(); + }); + } + } + finishBatch(replaced) { + const b = this.batch; this.batch = null; + if (!b) return; + this.onBatch({ tag: b.tag, files: b.files, done: b.done, skipped: b.skipped, bytes: b.bytes, + ms: Math.round(performance.now() - b.t0), replaced }); + if (!replaced && b.next) b.next(); + } + note(file) { + this.recent.delete(file); this.recent.set(file, 1); + while (this.recent.size > this.remember) this.recent.delete(this.recent.keys().next().value); + } + + async readFile(file) { + const buf = this.buffers.pop() || Buffer.allocUnsafe(256 * 1024); + const fh = await fs.promises.open(file, 'r'); + let total = 0; + try { + for (;;) { + const { bytesRead } = await fh.read(buf, 0, buf.length, total); + if (!bytesRead) break; + total += bytesRead; + } + } finally { await fh.close(); this.buffers.push(buf); } + return total; + } +} + +module.exports = { ReadAhead }; diff --git a/perf/trace.js b/perf/trace.js new file mode 100644 index 0000000..f4bd0aa --- /dev/null +++ b/perf/trace.js @@ -0,0 +1,173 @@ +'use strict'; +/* + * Switchable performance trace: one JSON object per line in DATA/perf/trace-YYYY-MM-DD.jsonl. + * + * On while PERF_TRACE=1 or while the file DATA/perf/trace.on exists (checked every few seconds, so it can be + * switched on a running server with `touch` / `rm`). Off, every call is a cheap no-op. + * + * Event kinds (field `k`): `req` one HTTP request with its phases, `client` timings the reader page reports, + * `loop` event-loop lag / CPU / memory every SAMPLE_MS, `nas` a periodic read of one uncached library page, + * `scan` library scans, `scraper` calls to the scraper daemon, `ahead` read-ahead batches, `trace` on/off. + * The format and the report tool: docs/performance.md, tools/perf-report.js. + */ +const fs = require('fs'), path = require('path'), { monitorEventLoopDelay } = require('perf_hooks'); + +const CHECK_MS = 5000, FLUSH_MS = 1000, SAMPLE_MS = 5000; +const MAX_DAY_BYTES = 256 * 1024 * 1024; // a runaway trace never fills the data disk +const KEEP_DAYS = 14; + +class Tracer { + constructor({ dir, env = process.env, now = Date.now } = {}) { + this.dir = dir; this.now = now; + this.forced = env.PERF_TRACE === '1'; + this.flag = path.join(dir, 'trace.on'); + this.on = false; this.buf = []; this.day = ''; this.dayBytes = 0; this.dropped = 0; + this.timers = []; this.probe = null; this.probeMs = Math.max(10, +env.PERF_NAS_PROBE_SECONDS || 60) * 1000; + } + + start() { + this.check(); + this.timers.push(setInterval(() => this.check(), CHECK_MS).unref()); + this.timers.push(setInterval(() => this.flush(), FLUSH_MS).unref()); + return this; + } + stop() { for (const t of this.timers) clearInterval(t); this.timers = []; this.setOn(false); this.flush(); } + + check() { + let on = this.forced; + if (!on) try { fs.accessSync(this.flag); on = true; } catch { /* off */ } + this.setOn(on); + } + setOn(on) { + if (on === this.on) return; + if (on) { + this.on = true; + this.log({ k: 'trace', on: true, pid: process.pid, node: process.version }); + this.startSampler(); + } else { + this.log({ k: 'trace', on: false }); + this.on = false; + this.stopSampler(); + } + } + + log(event) { + if (!this.on) return; + this.buf.push(JSON.stringify({ t: this.now(), ...event })); + if (this.buf.length >= 500) this.flush(); + } + + flush() { + if (!this.buf.length) return; + const lines = this.buf.join('\n') + '\n'; this.buf = []; + const day = new Date(this.now()).toISOString().slice(0, 10); + try { + if (day !== this.day) { this.day = day; this.dayBytes = 0; fs.mkdirSync(this.dir, { recursive: true }); this.prune(); } + if (this.dayBytes + lines.length > MAX_DAY_BYTES) { this.dropped += lines.length; return; } + fs.appendFileSync(path.join(this.dir, `trace-${day}.jsonl`), lines); + this.dayBytes += lines.length; + } catch (error) { console.warn('[perf] trace write failed:', error.message); } + } + prune() { + const cutoff = new Date(this.now() - KEEP_DAYS * 864e5).toISOString().slice(0, 10); + for (const name of fs.readdirSync(this.dir)) { + const m = /^trace-(\d{4}-\d\d-\d\d)\.jsonl$/.exec(name); + if (m && m[1] < cutoff) fs.rmSync(path.join(this.dir, name), { force: true }); + } + } + + // Event-loop delay shows whether the reader itself (CPU, sync work) holds requests back. + startSampler() { + const h = monitorEventLoopDelay({ resolution: 10 }); h.enable(); + let cpu = process.cpuUsage(), at = process.hrtime.bigint(); + this.sampler = { h, timer: setInterval(() => { + const nowCpu = process.cpuUsage(), nowAt = process.hrtime.bigint(), wall = Number(nowAt - at) / 1000; + const mem = process.memoryUsage(); + this.log({ k: 'loop', lagP50: ms(h.percentile(50)), lagP99: ms(h.percentile(99)), lagMax: ms(h.max), + cpu: round(((nowCpu.user - cpu.user) + (nowCpu.system - cpu.system)) / wall * 100), rss: mb(mem.rss), heap: mb(mem.heapUsed) }); + h.reset(); cpu = nowCpu; at = nowAt; + }, SAMPLE_MS).unref() }; + this.startProbe(); + } + stopSampler() { + if (this.sampler) { clearInterval(this.sampler.timer); this.sampler.h.disable(); this.sampler = null; } + if (this.probe) { clearInterval(this.probe); this.probe = null; } + } + + // NAS probe: read one random library page now and then. A page picked at random out of a large library is + // almost never in the OS cache, so this measures the storage itself (and shows disks waking from standby). + setProbeSource(pick) { this.pick = pick; if (this.on) this.startProbe(); } + startProbe() { + if (this.probe || !this.pick) return; + const run = () => this.probeOnce().catch(() => {}); + this.probe = setInterval(run, this.probeMs).unref(); + setTimeout(run, 1000).unref(); + } + async probeOnce() { + const file = this.pick && this.pick(); + if (!file) return; + const t0 = performance.now(); + let st, bytes = 0, firstMs = null, error = null; + try { + st = await fs.promises.stat(file); + const statMs = performance.now() - t0; + const fh = await fs.promises.open(file, 'r'); + try { + const chunk = Buffer.allocUnsafe(256 * 1024); + for (;;) { + const { bytesRead } = await fh.read(chunk, 0, chunk.length, bytes); + if (firstMs === null) firstMs = performance.now() - t0; + if (!bytesRead) break; + bytes += bytesRead; + } + } finally { await fh.close(); } + this.log({ k: 'nas', statMs: round(statMs), firstMs: round(firstMs), ms: round(performance.now() - t0), bytes }); + } catch (e) { error = e.code || e.message; this.log({ k: 'nas', ms: round(performance.now() - t0), error }); } + } +} + +// Wraps one HTTP request: `mark(name)` stores the time since the request arrived, `set` adds fields, and the +// event is written when the response is done (or the client went away). Off, returns a shared no-op. +const NOOP = { mark() {}, set() {}, stream() {}, elapsed: () => 0, on: false }; +function requestTrace(tracer, req, res) { + if (!tracer.on) return NOOP; + const t0 = performance.now(), ev = { k: 'req', m: req.method, path: req.url.split('?')[0].slice(0, 300) }; + const trace = { + on: true, + mark(name) { ev[name] = round(performance.now() - t0); }, + elapsed: () => round(performance.now() - t0), + set(fields) { Object.assign(ev, fields); }, + // Splits a file stream's time into waiting for the disk and waiting for the client (TCP backpressure): + // pipe() pauses the file stream while the socket buffer is full and resumes it on 'drain'. + stream(src) { + let pausedAt = 0, waitNet = 0; + src.on('open', () => trace.mark('open')); + src.once('data', () => trace.mark('first')); + src.on('data', chunk => { ev.bytes = (ev.bytes || 0) + chunk.length; }); + src.on('pause', () => { pausedAt = performance.now(); }); + src.on('resume', () => { if (pausedAt) { waitNet += performance.now() - pausedAt; pausedAt = 0; } }); + src.on('end', () => { + trace.mark('readEnd'); + ev.netWait = round(waitNet); + ev.disk = round(Math.max(0, ev.readEnd - (ev.open || 0) - waitNet)); + }); + }, + }; + let done = false; + const finish = aborted => { + if (done) return; done = true; + ev.ms = round(performance.now() - t0); ev.status = res.statusCode; + if (aborted) ev.aborted = true; + ev.conn = req.socket._perfRequests = (req.socket._perfRequests || 0) + 1; // >1: keep-alive reuse + tracer.log(ev); + }; + res.on('finish', () => finish(false)); + res.on('close', () => finish(!res.writableFinished)); + return trace; +} + +const round = v => (v == null || Number.isNaN(v) ? null : Math.round(v * 10) / 10); +const ms = ns => round(ns / 1e6); +const mb = b => Math.round(b / 1048576); + +module.exports = { Tracer, requestTrace }; diff --git a/public/perf.js b/public/perf.js new file mode 100644 index 0000000..ecbfa12 --- /dev/null +++ b/public/perf.js @@ -0,0 +1,72 @@ +'use strict'; +/* + * Reader-side half of the performance trace (docs/performance.md). Only started when the server says its + * trace is on (`perf: true` in /api/chapter). It reports, in batches to POST api/perf: + * - `res` the browser's resource timing of every library image: queueing, connection, time to first byte, + * download, size, the server's own `stat` time and whether the connection was reused; + * - `view` a page turn (page/book mode): how long the new page(s) took to appear, and whether they were + * preloaded already; + * - `stall` flow mode: a page scrolled into view before its image had loaded, and how long it stayed empty. + */ +window.PerfTrace = { + start(pageName) { + let queue = [], on = true; + const push = e => { if (on) queue.push(e); }; + const rel = url => { try { return decodeURIComponent(new URL(url).pathname); } catch { return String(url); } }; + const flush = beacon => { + if (!queue.length || !on) return; + const body = JSON.stringify({ page: pageName, events: queue.splice(0, 300) }); + if (beacon && navigator.sendBeacon) navigator.sendBeacon('api/perf', new Blob([body], { type: 'application/json' })); + else fetch('api/perf', { method: 'POST', headers: { 'Content-Type': 'application/json' }, body, keepalive: true }) + .then(r => r.json()).then(r => { if (r.on === false) on = false; }).catch(() => {}); + }; + setInterval(() => flush(false), 5000); + addEventListener('pagehide', () => flush(true)); + push({ e: 'hello', ua: navigator.userAgent, conn: navigator.connection ? navigator.connection.effectiveType : '', + dpr: devicePixelRatio, vw: innerWidth, vh: innerHeight }); + + if (window.PerformanceObserver) { + new PerformanceObserver(list => { + for (const r of list.getEntries()) { + if (!/\/lib\//.test(r.name)) continue; + const st = (r.serverTiming || []).find(x => x.name === 'stat'); + push({ e: 'res', url: rel(r.name), at: r.startTime, + queue: r.requestStart ? r.requestStart - r.startTime : null, // waiting for a free connection + connect: r.connectEnd - r.connectStart, dns: r.domainLookupEnd - r.domainLookupStart, + ttfb: r.responseStart && r.requestStart ? r.responseStart - r.requestStart : null, + download: r.responseStart ? r.responseEnd - r.responseStart : null, + total: r.duration, size: r.transferSize, body: r.encodedBodySize, server: st ? st.duration : null, + proto: r.nextHopProtocol || '', cached: r.transferSize === 0 && r.encodedBodySize > 0 }); + } + }).observe({ type: 'resource', buffered: true }); + } + + return { + // Called right after a page turn put new elements on screen. + view(imgs, info) { + const t0 = performance.now(), waiting = imgs.filter(img => !img.complete); + const event = { e: 'view', ...info, n: imgs.length, preloaded: !waiting.length }; + if (!waiting.length) { push({ ...event, wait: 0 }); return; } + Promise.all(waiting.map(img => (img.decode ? img.decode() : Promise.resolve()).catch(() => {}))) + .then(() => requestAnimationFrame(() => push({ ...event, wait: performance.now() - t0, + url: rel(waiting[0].currentSrc || waiting[0].src) }))); + }, + // Flow mode: watch pages enter the real viewport (not the preload margin) before their image is there. + watchFlow(root, els) { + if (!window.IntersectionObserver) return; + const io = new IntersectionObserver(entries => { + for (const en of entries) { + const img = en.target.firstChild; + if (!en.isIntersecting || (img.complete && img.naturalWidth)) continue; + const t0 = performance.now(), hadSrc = !!img.getAttribute('src'); + const done = () => push({ e: 'stall', wait: performance.now() - t0, hadSrc, url: rel(img.currentSrc || img.src) }); + img.addEventListener('load', done, { once: true }); + io.unobserve(en.target); + } + }, { root }); + for (const el of els) io.observe(el); + return io; + }, + }; + }, +}; diff --git a/public/read.html b/public/read.html index f3c0ce5..b282e85 100644 --- a/public/read.html +++ b/public/read.html @@ -16,6 +16,7 @@ + diff --git a/public/reader.js b/public/reader.js index 81dbfc1..4971301 100644 --- a/public/reader.js +++ b/public/reader.js @@ -74,6 +74,9 @@ D = payload; } catch (e) { canvas.textContent = ''; canvas.append(h('p', { class: 'loading' }, e.message + ' · ', h('a', { href: './' }, 'Library'))); return; } + // Timings for the server's performance trace, only while an admin has it switched on. + const perf = D.perf && window.PerfTrace ? PerfTrace.start('read') : null; + let perfFlow = null; // An already-open chapter also closes when a window ends or an unlock expires. const checkReadingAccess = async () => { @@ -250,11 +253,13 @@ if (mode === 'flow') { els = list.map(p => canvas.appendChild(pageEl(p, true))); endEl = canvas.appendChild(endCard()); + if (perf) { if (perfFlow) perfFlow.disconnect(); perfFlow = perf.watchFlow(stage, els); } } else if (atEnd) { endEl = canvas.appendChild(endCard()); } else { shown = mode === 'page' ? [cur] : spreads[spreadIdx]; els = shown.map(k => canvas.appendChild(pageEl(list[k]))); + if (perf) perf.view(els.map(el => el.firstChild), { mode, page: list[shown[0]].i }); // The pages on screen get the bandwidth first, then the next ones are fetched. const token = ++buildToken, waiting = els.map(el => el.firstChild).filter(img => !img.complete); Promise.all(waiting.map(img => new Promise(done => { diff --git a/server.js b/server.js index 3667a64..bce53ee 100644 --- a/server.js +++ b/server.js @@ -12,6 +12,8 @@ * SCRAPER_URL=http://127.0.0.1:8091 scraper daemon API * SCRAPER_TOKEN=... shared daemon token (optional on loopback) * BACKUP=/backup folder for built-in DATA backups (unset = backups off) + * READ_AHEAD=1 read an opened chapter's pages (then the next chapter's) into the OS cache, 0 = off + * PERF_TRACE=1 performance trace to DATA/perf/ (or touch DATA/perf/trace.on at runtime; docs/performance.md) */ const http = require('http'), fs = require('fs'), path = require('path'), crypto = require('crypto'); const { scanLibrary, scanChangedLibrary, libraryStamps, snapshotIndex, restoreIndex } = require('./library'); @@ -36,6 +38,8 @@ const { chapterDates } = require('./chapter-dates'); const { parseSchedule, publicSchedule, loadQuestionBank, createReadingAccess } = require('./reading-access'); const { BackupService, BackupError } = require('./backup'); const moments = require('./moments'); +const { Tracer, requestTrace } = require('./perf/trace'); +const { ReadAhead } = require('./perf/read-ahead'); const PORT = +process.env.PORT || 8080; const LIB = path.resolve(process.env.LIBRARY || 'library'); @@ -64,6 +68,9 @@ const MIME = { // ---------- storage: one JSON file, written atomically ---------- fs.mkdirSync(DATA, { recursive: true }); +const tracer = new Tracer({ dir: path.join(DATA, 'perf') }).start(); +const readAhead = process.env.READ_AHEAD === '0' ? null + : new ReadAhead({ onBatch: batch => tracer.log({ k: 'ahead', ...batch }) }); const catalog = new Catalog(DATA); const greatestCatalog = loadGreatestCatalog(); const greatestById = new Map(greatestCatalog.entries.map(entry => [entry.id, entry])); @@ -175,8 +182,10 @@ async function performScan(mode) { scanState = { at: Date.now(), ms: Date.now() - t0, mode, changedMangas: changed.length, mangas: lib.mangas.length, chapters, pages, stale: false, error: null }; console.log(`[scan] ${mode}: ${changed.length} changed manga, ${lib.mangas.length} manga, ${chapters} chapters, ${pages} pages in ${scanState.ms} ms`); + tracer.log({ k: 'scan', mode, ms: scanState.ms, changed: changed.length }); return scanState; } catch (e) { + tracer.log({ k: 'scan', mode, ms: Date.now() - t0, error: e.message }); scanState = { ...scanState, at: Date.now(), error: e.message }; console.error('[scan] failed:', e.message); return scanState; @@ -253,9 +262,14 @@ async function scraperRequest(endpoint, body) { options.method = 'POST'; headers['content-type'] = 'application/json'; options.body = JSON.stringify(body); } let response; + const t0 = performance.now(); try { response = await fetch(SCRAPER_URL + endpoint, options); } - catch (error) { throw new HttpError(503, `Scraper service unavailable: ${error.message}`); } + catch (error) { + tracer.log({ k: 'scraper', endpoint, ms: Math.round(performance.now() - t0), error: error.message }); + throw new HttpError(503, `Scraper service unavailable: ${error.message}`); + } const data = await response.json().catch(() => ({})); + tracer.log({ k: 'scraper', endpoint, ms: Math.round(performance.now() - t0), status: response.status }); if (!response.ok) throw new HttpError(response.status >= 500 ? 502 : response.status, data.error || `Scraper HTTP ${response.status}`); return data; } @@ -433,6 +447,17 @@ function continueOf(m, prog, s) { const next = m.chapters.slice(m.chapters.indexOf(last.ch) + 1).find(ok); return next ? { c: next.id, text: 'Read next · ' + next.label } : { c: last.ch.id, v: last.p.v, text: 'Read again · ' + last.ch.label }; } +// From the saved page on, then the pages before it; afterwards the next chapter's preferred version. +function warmChapter(m, ch, v, progress, s) { + const from = Math.min(Math.max(0, +(progress && progress.v === v.id && progress.p) || 0), v.pages.length); + const pages = v.pages.slice(from).concat(v.pages.slice(0, from)).map(p => path.join(LIB, v.rel, p.f)); + readAhead.warm(pages, `${m.id}/${ch.id}`); + const next = neighbour(m, ch, 1, s), nextCh = next && m.chapterById.get(next.id); + if (nextCh) { + const nv = ranked(m, nextCh)[0].v; + readAhead.then(nv.pages.map(p => path.join(LIB, nv.rel, p.f)), `${m.id}/${nextCh.id}`); + } +} function neighbour(m, ch, step, s) { for (let i = m.chapters.indexOf(ch) + step; i >= 0 && i < m.chapters.length; i += step) { const c = m.chapters[i]; @@ -743,7 +768,9 @@ const routes = { let seen = false; for (const n of db.notes[u.name] || []) if (!n.read && n.m === m.id && n.c === ch.id) seen = n.read = true; if (seen) save(); + if (readAhead) warmChapter(m, ch, v, prog[ch.id], s); return { + perf: tracer.on, manga: { id: m.id, title: m.title }, chapter: { id: ch.id, label: ch.label, title: ch.title, extra: ch.extra }, version: v.id, versions: versionsOf(m, ch, u), direction: v.direction, @@ -875,6 +902,21 @@ const routes = { return { ok: true }; }, + // Timings the reader page measured (resource timing, decode, page-turn waits) while the trace is on. + 'POST /api/perf': ({ u, b }) => { + if (!tracer.on) return { on: false }; + const events = Array.isArray(b.events) ? b.events.slice(0, 300) : []; + for (const e of events) if (e && typeof e === 'object' && !Array.isArray(e)) { + const clean = {}; + for (const [key, value] of Object.entries(e).slice(0, 30)) { + if (key === 't' || key === 'k') continue; // the server's clock and kind + if (typeof value === 'number' && Number.isFinite(value)) clean[key] = Math.round(value * 10) / 10; + else if (typeof value === 'string' || typeof value === 'boolean') clean[key] = typeof value === 'string' ? value.slice(0, 300) : value; + } + tracer.log({ ...clean, k: 'client', user: u.name, page: b.page ? String(b.page).slice(0, 40) : undefined }); + } + return { on: true }; + }, 'GET /api/notifications': ({ u }) => ({ items: (db.notes[u.name] || []).slice().reverse() }), 'POST /api/notifications/read': ({ u, b }) => { for (const n of db.notes[u.name] || []) if (b.all || n.id === b.id) n.read = true; @@ -1062,21 +1104,28 @@ async function handleApi(req, res, u, route, q) { } sendJson(res, 200, await route({ req, res, u, b, q })); } -function serveFile(req, res, root, rel, cacheControl, only) { +function serveFile(req, res, root, rel, cacheControl, only, trace) { let file; try { file = path.resolve(root, decodeURIComponent(rel)); } catch { return sendJson(res, 400, { error: 'Bad path' }); } if (!file.startsWith(root + path.sep) || (only && !only.test(file))) return sendJson(res, 404, { error: 'Not found' }); fs.stat(file, (err, st) => { + if (trace) trace.mark('stat'); if (err || !st.isFile()) return sendJson(res, 404, { error: 'Not found' }); const etag = `"${st.size.toString(36)}-${Math.round(st.mtimeMs).toString(36)}"`; if (req.headers['if-none-match'] === etag) { res.writeHead(304, { ETag: etag, 'Cache-Control': cacheControl }); return res.end(); } - res.writeHead(200, { 'Content-Type': MIME[path.extname(file).toLowerCase()] || 'application/octet-stream', 'Content-Length': st.size, ETag: etag, 'Cache-Control': cacheControl }); + const headers = { 'Content-Type': MIME[path.extname(file).toLowerCase()] || 'application/octet-stream', 'Content-Length': st.size, ETag: etag, 'Cache-Control': cacheControl }; + // The browser's resource timing shows this, so a slow page can be matched to the server's share. + if (trace && trace.on) headers['Server-Timing'] = `stat;dur=${trace.elapsed()}`; + res.writeHead(200, headers); if (req.method === 'HEAD') return res.end(); - fs.createReadStream(file).on('error', () => res.destroy()).pipe(res); + const stream = fs.createReadStream(file).on('error', () => res.destroy()); + if (trace) trace.stream(stream); + stream.pipe(res); }); } http.createServer(async (req, res) => { + const trace = requestTrace(tracer, req, res); try { const { pathname, searchParams } = new URL(req.url, 'http://localhost'); const u = userOf(req); @@ -1124,9 +1173,10 @@ http.createServer(async (req, res) => { const parts = relative.split(path.sep); if (parts.length >= 4 && !readingAccess.status(u.name).allowed) bad(423, 'Reading is outside the deployment schedule.'); - return serveFile(req, res, LIB, pathname.slice(5), readingSchedule && parts.length >= 4 ? 'private, no-store' : 'private, max-age=86400', IMG); + trace.mark('access'); + return serveFile(req, res, LIB, pathname.slice(5), readingSchedule && parts.length >= 4 ? 'private, no-store' : 'private, max-age=86400', IMG, trace); } - serveFile(req, res, PUB, pathname === '/' ? 'index.html' : pathname.slice(1), 'no-cache'); + serveFile(req, res, PUB, pathname === '/' ? 'index.html' : pathname.slice(1), 'no-cache', null, trace); } catch (e) { const expected = e instanceof HttpError || e instanceof CatalogError || e instanceof moments.MomentError; if (!expected) console.error(e); @@ -1134,6 +1184,13 @@ http.createServer(async (req, res) => { } }).listen(PORT, () => console.log(`MangaCircus on http://localhost:${PORT} (library: ${LIB}, data: ${DATA})`)); +// The trace's storage probe reads a random page of the library (rarely in the OS cache). +tracer.setProbeSource(() => { + const m = lib.mangas[Math.floor(Math.random() * lib.mangas.length)]; + const ch = m && m.chapters[Math.floor(Math.random() * m.chapters.length)], v = ch && ch.versions[0]; + const p = v && v.pages[Math.floor(Math.random() * v.pages.length)]; + return p ? path.join(LIB, v.rel, p.f) : null; +}); if (lib.mangas.length) refreshChanged(); else rescan(); if (SCAN_MINUTES > 0) setInterval(() => refreshChanged(), SCAN_MINUTES * 60000).unref(); diff --git a/test/dockerfile.test.js b/test/dockerfile.test.js index dbc41e3..dfe2d83 100644 --- a/test/dockerfile.test.js +++ b/test/dockerfile.test.js @@ -3,6 +3,7 @@ const test = require('node:test'), assert = require('node:assert/strict'); const fs = require('fs'), path = require('path'); const root = path.resolve(__dirname, '..'); +const allowedNames = () => new Set(fs.readFileSync(path.join(root, '.dockerignore'), 'utf8').split(/\r?\n/).filter(line => line.startsWith('!')).map(line => line.slice(1))); test('every top-level module the reader requires is copied into the image', () => { const dockerfile = fs.readFileSync(path.join(root, 'Dockerfile'), 'utf8'); @@ -12,14 +13,19 @@ test('every top-level module the reader requires is copied into the image', () = const file = pending.pop(); if (seen.has(file)) continue; seen.add(file); - for (const [, name] of fs.readFileSync(path.join(root, file), 'utf8').matchAll(/require\('\.\/([\w.-]+?)(?:\.js)?'\)/g)) { + const source = fs.readFileSync(path.join(root, file), 'utf8'); + for (const [, dir] of source.matchAll(/require\('\.\/([\w.-]+)\/[^']+'\)/g)) { + assert.ok(copied.has(dir), `${dir}/ is not copied`); + assert.ok(allowedNames().has(dir + '/'), `${dir}/ is not allowed through .dockerignore`); + } + for (const [, name] of source.matchAll(/require\('\.\/([\w.-]+?)(?:\.js)?'\)/g)) { // A folder (e.g. ./greatest) is copied as a whole; only single files need their own name in COPY. if (fs.existsSync(path.join(root, name)) && fs.statSync(path.join(root, name)).isDirectory()) assert.ok(copied.has(name), `${name}/ is not copied`); else pending.push(name + '.js'); } } // .dockerignore is an allowlist too: a file not let through never reaches COPY. - const allowed = new Set(fs.readFileSync(path.join(root, '.dockerignore'), 'utf8').split(/\r?\n/).filter(line => line.startsWith('!')).map(line => line.slice(1))); + const allowed = allowedNames(); for (const file of seen) { assert.ok(copied.has(file), `${file} is required but not copied by the Dockerfile`); assert.ok(allowed.has(file), `${file} is required but not allowed through .dockerignore`); diff --git a/test/perf.test.js b/test/perf.test.js new file mode 100644 index 0000000..0dd46ef --- /dev/null +++ b/test/perf.test.js @@ -0,0 +1,104 @@ +'use strict'; +const test = require('node:test'), assert = require('node:assert/strict'); +const fs = require('fs'), os = require('os'), path = require('path'), http = require('http'); +const { Tracer, requestTrace } = require('../perf/trace'); +const { ReadAhead } = require('../perf/read-ahead'); +const { analyse } = require('../tools/perf-report'); + +const tmp = () => fs.mkdtempSync(path.join(os.tmpdir(), 'circus-perf-')); +const lines = dir => fs.readdirSync(dir).filter(n => n.endsWith('.jsonl')) + .flatMap(n => fs.readFileSync(path.join(dir, n), 'utf8').trim().split('\n')).filter(Boolean).map(JSON.parse); + +test('tracer is off without the flag file and writes nothing', () => { + const dir = tmp(), tracer = new Tracer({ dir, env: {} }); + tracer.check(); tracer.log({ k: 'x' }); tracer.flush(); + assert.equal(tracer.on, false); + assert.deepEqual(fs.readdirSync(dir), []); +}); + +test('the flag file switches the trace on and off at runtime', () => { + const dir = tmp(), tracer = new Tracer({ dir, env: {} }); + fs.writeFileSync(path.join(dir, 'trace.on'), ''); + tracer.check(); tracer.log({ k: 'x', a: 1 }); + fs.rmSync(path.join(dir, 'trace.on')); + tracer.check(); tracer.log({ k: 'x', a: 2 }); tracer.flush(); + const events = lines(dir); + assert.deepEqual(events.map(e => e.k), ['trace', 'x', 'trace']); + assert.equal(events[1].a, 1); + assert.equal(events[2].on, false); + assert.ok(events.every(e => typeof e.t === 'number')); +}); + +test('a served file is traced with storage and network phases', async () => { + const dir = tmp(), tracer = new Tracer({ dir, env: { PERF_TRACE: '1' } }); + tracer.check(); + const file = path.join(dir, 'page.jpg'); + fs.writeFileSync(file, Buffer.alloc(3 * 1024 * 1024, 7)); + const server = http.createServer((req, res) => { + const trace = requestTrace(tracer, req, res); + fs.stat(file, (err, st) => { + trace.mark('stat'); + res.writeHead(200, { 'Content-Length': st.size }); + const stream = fs.createReadStream(file); + trace.stream(stream); + stream.pipe(res); + }); + }); + await new Promise(r => server.listen(0, r)); + const { port } = server.address(); + const r = await fetch(`http://127.0.0.1:${port}/lib/M/B/C/page.jpg`); + assert.equal((await r.arrayBuffer()).byteLength, 3 * 1024 * 1024); + await new Promise(r => setTimeout(r, 50)); + server.close(); tracer.stopSampler(); tracer.flush(); + const req = lines(dir).find(e => e.k === 'req'); + assert.equal(req.status, 200); + assert.equal(req.bytes, 3 * 1024 * 1024); + assert.equal(req.path, '/lib/M/B/C/page.jpg'); + for (const field of ['stat', 'open', 'first', 'readEnd', 'disk', 'netWait', 'ms']) assert.equal(typeof req[field], 'number', field); + assert.ok(req.ms >= req.readEnd && req.readEnd >= req.first && req.first >= req.open); +}); + +test('read-ahead reads files in order and a newer chapter replaces the queued one', async () => { + const dir = tmp(), files = []; + for (let i = 0; i < 6; i++) { const f = path.join(dir, `p${i}.jpg`); fs.writeFileSync(f, Buffer.alloc(1000 + i)); files.push(f); } + const batches = []; + const ahead = new ReadAhead({ concurrency: 1, onBatch: b => batches.push(b) }); + const done = new Promise(resolve => { const check = () => (batches.some(b => b.tag === 'B' && !b.replaced) ? resolve() : setTimeout(check, 5)); check(); }); + ahead.warm(files.slice(0, 4), 'A'); + ahead.warm(files.slice(3), 'B'); + await done; + assert.equal(batches[0].tag, 'A'); assert.equal(batches[0].replaced, true); + const b = batches.find(x => x.tag === 'B'); + assert.equal(b.done, 3); assert.equal(b.bytes, 1003 + 1004 + 1005); + // Files read recently are skipped the next time. + batches.length = 0; + ahead.warm(files.slice(4), 'C'); + assert.deepEqual(batches.map(x => [x.tag, x.files, x.skipped]), [['C', 0, 2]]); +}); + +test('read-ahead runs the follow-up batch after the current one', async () => { + const dir = tmp(), a = path.join(dir, 'a.jpg'), b = path.join(dir, 'b.jpg'); + fs.writeFileSync(a, 'a'); fs.writeFileSync(b, 'bb'); + const tags = []; + const ahead = new ReadAhead({ onBatch: x => tags.push(x.tag) }); + ahead.warm([a], 'now'); ahead.then([b], 'next'); + await new Promise(r => { const check = () => (tags.length === 2 ? r() : setTimeout(check, 5)); check(); }); + assert.deepEqual(tags, ['now', 'next']); +}); + +test('the report blames the storage for slow first reads', () => { + const t = Date.parse('2026-10-29T20:00:00Z'); + const events = [ + { t, k: 'req', m: 'GET', path: '/lib/M/B/C/1.jpg', status: 200, bytes: 300000, stat: 2, open: 3, first: 1900, readEnd: 1950, disk: 1947, netWait: 0, ms: 1955, conn: 1 }, + { t: t + 1000, k: 'req', m: 'GET', path: '/lib/M/B/C/2.jpg', status: 200, bytes: 300000, stat: 1, open: 2, first: 5, readEnd: 20, disk: 18, netWait: 0, ms: 22, conn: 2 }, + { t: t + 2000, k: 'client', e: 'res', url: '/lib/M/B/C/1.jpg', total: 2100, ttfb: 30, download: 2000, queue: 1, connect: 0, dns: 0 }, + { t: t + 3000, k: 'client', e: 'view', wait: 2050, preloaded: false }, + { t: t + 4000, k: 'nas', firstMs: 2500, ms: 2600, bytes: 1 }, + ]; + const o = analyse(events, { slow: 500 }); + assert.equal(o.slowServer.count, 1); + assert.deepEqual(o.slowServer.by, { firstRead: 1 }); + assert.deepEqual(o.slowBrowser.by, { server: 1 }); + assert.equal(o.pageTurns.over1s, 1); + assert.match(o.verdict.join('\n'), /first read from storage/); +}); diff --git a/tools/perf-bench.js b/tools/perf-bench.js new file mode 100644 index 0000000..95c6d30 --- /dev/null +++ b/tools/perf-bench.js @@ -0,0 +1,110 @@ +#!/usr/bin/env node +'use strict'; +/* + * Load test for the reader: N simulated readers each open random chapters and fetch the pages one after + * another with a think time, the way a person paging through a chapter does, plus a small look-ahead. + * Measures time to first byte and total per page from this machine. Read-only apart from the login; it + * never writes progress. Run it with the server's trace on to see the server's share (docs/performance.md). + * + * node tools/perf-bench.js --url http://host:8080 --user bench --password-env BENCH_PASSWORD \ + * [--readers 4] [--chapters 3] [--pages 40] [--think 400] [--ahead 2] [--manga Berserk] [--json] + * --cookie 'sid=…' instead of user/password. --chapter-only skips the page fetches (API timings only). + */ + +function parseArgs(argv) { + const o = { url: 'http://localhost:8080', readers: 4, chapters: 3, pages: 40, think: 400, ahead: 2, manga: '', json: false }; + for (let i = 0; i < argv.length; i++) { + const key = argv[i].replace(/^--/, ''), next = () => argv[++i]; + if (['readers', 'chapters', 'pages', 'think', 'ahead'].includes(key)) o[key] = +next(); + else if (key === 'password-env') o.password = process.env[next()] || ''; + else if (['url', 'user', 'cookie', 'manga'].includes(key)) o[key] = next(); + else if (key === 'json' || key === 'chapter-only') o[key.replace('-o', 'O')] = true; + else if (key === 'h' || key === 'help') o.help = true; + } + o.url = o.url.replace(/\/$/, ''); + return o; +} + +async function login(o) { + if (o.cookie) return o.cookie; + const r = await fetch(o.url + '/api/login', { method: 'POST', headers: { 'content-type': 'application/json' }, + body: JSON.stringify({ name: o.user, password: o.password }) }); + if (!r.ok) throw new Error(`login failed: HTTP ${r.status} ${await r.text()}`); + const cookie = (r.headers.get('set-cookie') || '').split(';')[0]; + if (!cookie) throw new Error('login returned no session cookie'); + return cookie; +} + +async function timed(url, cookie) { + const t0 = performance.now(); + const r = await fetch(url, { headers: { cookie } }); + const ttfb = performance.now() - t0; + let bytes = 0; + for await (const chunk of r.body) bytes += chunk.length; + return { status: r.status, ttfb, ms: performance.now() - t0, bytes, server: r.headers.get('server-timing') || '' }; +} +const json = async (o, cookie, path) => { + const t0 = performance.now(), r = await fetch(o.url + path, { headers: { cookie } }); + if (!r.ok) throw new Error(`${path}: HTTP ${r.status}`); + return { data: await r.json(), ms: performance.now() - t0 }; +}; +const pick = list => list[Math.floor(Math.random() * list.length)]; +const sleep = ms => new Promise(r => setTimeout(r, ms)); + +async function reader(o, cookie, mangas, out, id) { + for (let c = 0; c < o.chapters; c++) { + const m = pick(mangas); + const manga = await json(o, cookie, '/api/manga?m=' + encodeURIComponent(m.id)); + out.api.push({ path: '/api/manga', ms: manga.ms }); + const ch = pick(manga.data.chapters); + const chapter = await json(o, cookie, `/api/chapter?m=${encodeURIComponent(m.id)}&c=${encodeURIComponent(ch.id)}`); + out.api.push({ path: '/api/chapter', ms: chapter.ms }); + if (o.chapterOnly) continue; + const pages = chapter.data.pages.slice(0, o.pages); + // The browser keeps `ahead` pages in flight while the reader looks at the current one. + const inflight = new Map(); + const start = k => { if (k < pages.length && !inflight.has(k)) inflight.set(k, timed(o.url + '/' + pages[k].u, cookie)); }; + for (let k = 0; k < pages.length; k++) { + const waitFrom = performance.now(); + start(k); + for (let a = 1; a <= o.ahead; a++) start(k + a); + const r = await inflight.get(k); + out.pages.push({ reader: id, manga: m.id, chapter: ch.id, page: k, wait: performance.now() - waitFrom, ...r }); + await sleep(o.think * (0.5 + Math.random())); + } + await Promise.all(inflight.values()); + } +} + +const pct = (v, p) => { const s = v.slice().sort((a, b) => a - b); return s.length ? Math.round(s[Math.min(s.length - 1, Math.floor(p / 100 * s.length))]) : null; }; +const sum = v => ({ n: v.length, p50: pct(v, 50), p90: pct(v, 90), p99: pct(v, 99), max: v.length ? Math.round(Math.max(...v)) : null }); + +async function main() { + const o = parseArgs(process.argv.slice(2)); + if (o.help || (!o.cookie && !o.user)) { + console.log('usage: node tools/perf-bench.js --url URL (--user NAME --password-env VAR | --cookie sid=…) [--readers N] [--chapters N] [--pages N] [--think ms] [--ahead N] [--manga text] [--chapter-only] [--json]'); + process.exit(o.help ? 0 : 2); + } + const cookie = await login(o); + let mangas = (await json(o, cookie, '/api/library')).data.mangas; + if (o.manga) mangas = mangas.filter(m => m.title.toLowerCase().includes(o.manga.toLowerCase())); + if (!mangas.length) throw new Error('no manga to read'); + const out = { pages: [], api: [] }, t0 = Date.now(); + await Promise.all(Array.from({ length: o.readers }, (_, i) => reader(o, cookie, mangas, out, i))); + const ok = out.pages.filter(p => p.status === 200), mb = ok.reduce((a, p) => a + p.bytes, 0) / 1048576; + const result = { + readers: o.readers, seconds: Math.round((Date.now() - t0) / 1000), pages: out.pages.length, errors: out.pages.length - ok.length, + MB: Math.round(mb), wait: sum(ok.map(p => p.wait)), ttfb: sum(ok.map(p => p.ttfb)), total: sum(ok.map(p => p.ms)), + waitedOver300: ok.filter(p => p.wait >= 300).length, waitedOver1s: ok.filter(p => p.wait >= 1000).length, + api: Object.fromEntries([...new Set(out.api.map(a => a.path))].map(p => [p, sum(out.api.filter(a => a.path === p).map(a => a.ms))])), + worst: ok.sort((a, b) => b.wait - a.wait).slice(0, 8).map(p => ({ wait: Math.round(p.wait), ttfb: Math.round(p.ttfb), ms: Math.round(p.ms), kb: Math.round(p.bytes / 1024), at: `${p.manga} ${p.chapter} p${p.page}` })), + }; + if (o.json) return console.log(JSON.stringify(result, null, 2)); + console.log(`${result.readers} readers, ${result.pages} pages (${result.MB} MB) in ${result.seconds} s, ${result.errors} errors`); + for (const k of ['wait', 'ttfb', 'total']) console.log(` ${k.padEnd(6)} ms ${JSON.stringify(result[k])}`); + console.log(` page waits >= 300 ms: ${result.waitedOver300}, >= 1 s: ${result.waitedOver1s} (wait = time the reader looked at an empty page)`); + for (const [p, s] of Object.entries(result.api)) console.log(` ${p} ${JSON.stringify(s)}`); + for (const w of result.worst) console.log(` wait ${w.wait} ms (ttfb ${w.ttfb}, total ${w.ms}, ${w.kb} KB) ${w.at}`); +} + +main().catch(e => { console.error(e.message); process.exit(1); }); diff --git a/tools/perf-report.js b/tools/perf-report.js new file mode 100644 index 0000000..809e6a4 --- /dev/null +++ b/tools/perf-report.js @@ -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 ... [--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 };