MaashkinoozheandClaude Opus 5.5
896726a51b
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>
79 lines
4.9 KiB
Markdown
79 lines
4.9 KiB
Markdown
# 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).
|