diff --git a/PHASE2-FINDINGS.md b/PHASE2-FINDINGS.md index 73b26a2c7..cd50be803 100644 --- a/PHASE2-FINDINGS.md +++ b/PHASE2-FINDINGS.md @@ -609,6 +609,118 @@ This is also the worst case for the round-trip trade-off: that one event name co sequential requests. It did not show up in board load latency (523 ms vs 526 ms median), because the widget fetches after the board renders, and total CPU rose 4%. +## Dissecting the peak, not the idle + +Everything above measures a drained process — boot idle, or post-soak. That is the wrong +moment: users complain about the high-water mark. Measuring it needs different instruments, +because the obvious one cannot work. + +**A heap snapshot can never explain a peak.** V8 runs a full GC before serialising one, so by +construction it reports what survived. The 94 MiB of ArrayBuffers that drove this container to +500 MB was invisible in every snapshot taken. Three instruments were added instead: + +| instrument | what it sees | blind to | +| --- | --- | --- | +| `HeapProfiler.startSampling` (in-process `inspector.Session`) | every V8-heap allocation, survivor or garbage, with a stack | anything outside the V8 heap | +| wrapped `Buffer.alloc`/`concat` | external buffer allocations, with a stack | V8-heap objects | +| `/proc//smaps` at every stage | JS heap vs JIT vs native vs file-backed | anything below page granularity | + +Together they cover the whole address space. Neither of the first two alone would have found +the Umami bug: the sampling profiler cannot see `Buffer` backing stores, which is precisely +where those 46 MiB lived. + +### An observer effect worth recording + +The first attempt took the peak snapshot over CDP, which delivers it as JS string chunks. For +a ~135 MB snapshot that added **~134 MiB of ArrayBuffers to the process being measured**, and +the stage right after it read 693.7 MiB. That is an artefact, not an application problem — +and it is exactly the kind of number that gets reported as a finding. Switching to +`v8.writeHeapSnapshot`, which streams from C++, removed it. The probe now reports its own +`observerCostMiB` so the cost of looking is visible rather than assumed to be zero. + +### What the peak is actually made of + +Peak here is `nav-01`, not the multi-tab stage — a GC lands during multi-tab and pulls RSS +*down*, so "most tabs open" is not the same as "most memory". Node RSS 357.8 MiB: + +| component | MiB | notes | +| --- | --- | --- | +| live JS objects (`heapUsed`) | 175.7 | of which ~41 MiB is retained bundle source | +| node binary text | 65.7 | file-backed and shared; not in cgroup `anon` | +| native malloc | ~59 | see below | +| external buffers | 24.6 | | +| V8 committed but free | 12.3 | heapTotal − heapUsed | +| JIT code | 10.1 | grew from 1.9 MiB at boot | + +Cross-checked rather than assumed: `heapTotal 188.0 − V8's 256 KiB pages 153.1 = 34.9 MiB`, +which matches `large_object_space` at 34.5 MiB. So the handful of very large anonymous +mappings (31.6, 20.7, 8.4 MiB) are V8's large-object space and external buffers — **not** the +runaway native allocator that their shape first suggested. + +**The retained heap at peak is the same as at rest.** A post-GC snapshot at peak has 160.7 MiB +of shallow size against 157.7 MiB after the soak; strings 51.1 vs 50.1 MiB. Nothing +accumulates. The peak is transient churn plus pages V8 and malloc have not returned — which is +why memory "oscillates" and why soak growth is negative. + +And the churn is small now: total V8-heap allocation across the entire run is **125 MiB**, 40% +of it node's own module loader reading source files. After the Umami fix the multi-tab burst +allocates **3.3 MiB**. There is no longer a churn problem on the JS side. + +## The 16 MiB nobody was using: ssh2 + +The largest single retainer in every snapshot — at boot, at peak, and after the soak — was one +`system / Context` holding **16.03 MiB**. Expanding it through the dominator tree (a plain +graph walk escapes via `__proto__` and reports the whole heap) named it immediately: + +``` +=== inside the largest retainer (object:system / Context, 16.03 MiB) === + 16.00 MiB (indirect) -> object:ArrayBuffer + 0.00 MiB POLY1305_WASM_MODULE -> object:Object + 0.00 MiB ChaChaPolyCipherNative -> closure:ChaChaPolyCipherNative + 0.00 MiB AESGCMCipherNative -> closure:AESGCMCipherNative +``` + +`ssh2`. Its crypto module instantiates a WebAssembly memory for ChaCha20-Poly1305 the moment +it is required. Homarr has no SSH feature and does not depend on ssh2; the chain is +`dockerode → docker-modem → ssh2`, and `docker-modem/lib/modem.js` requires `./ssh` at module +scope while using it in exactly one place, already guarded by `protocol === 'ssh'`. + +Measured directly inside the image — requiring ssh2 and nothing else: + +``` +heapUsed +2.6 MiB external +0.9 MiB rss +14.0 MiB +``` + +Fixed with a pnpm patch moving that one require inside the branch that uses it. SSH-based +Docker hosts still work — `require` is cached, so they pay it once — and socket-based installs, +which is everyone else, never load it. + +### The same question asked of every dependency + +Since one package was hiding 14 MiB behind a require, all 173 were measured the same way: each +required in a fresh process, RSS delta recorded. Packages costing more than 2 MiB, cross-checked +against whether the server actually loads them: + +| package | RSS to require | loaded at runtime? | +| --- | --- | --- | +| drizzle-orm | 124.3 MiB | only via subpaths — the root import loads every dialect, so this figure overstates it | +| @kubernetes/client-node | 66.9 MiB | **no** — correctly lazy | +| dockerode | 28.8 MiB | yes (includes docker-modem 16.1 and ssh2 14.3) | +| **mysql2** | **20.9 MiB** | **yes — 77 files, on a SQLite install** | +| sharp | 20.4 MiB | no | +| openid-client / jose | 16.1 / 15.5 MiB | no | +| @grpc/grpc-js | 14.6 MiB | yes, 61 files (via dockerode) | +| **pg** | **9.4 MiB** | **yes — 13 files, on a SQLite install** | + +These are not additive — dockerode's figure contains ssh2's — but the ranking is what matters. + +**mysql2 and pg are loaded on every SQLite install.** `db/drivers/index.ts` statically imports +all three driver wrappers and picks one at call time, so importing the module executes all +three. Not yet fixed: `packages/db/index.ts` does `export const db = createDb(schema)` at +module scope, so `createDb` must stay synchronous and cannot use `await import()`. The viable +route is deferring the external `require` inside each wrapper. Both dialects have testcontainer +migration tests, so it is verifiable — it is queued, not dismissed. + ## Why 24 MiB of code is resident before the first request The module cache is a flat list with no parentage, so "what pulled this in" needed the diff --git a/patches/docker-modem@5.0.7.patch b/patches/docker-modem@5.0.7.patch new file mode 100644 index 000000000..e325c7582 --- /dev/null +++ b/patches/docker-modem@5.0.7.patch @@ -0,0 +1,27 @@ +diff --git a/lib/modem.js b/lib/modem.js +index b45a798d63647d55e0193fd7e82c2e36785d9b5f..d2dbf42969fc0ebf39b30c1a27373c33c2d20333 100644 +--- a/lib/modem.js ++++ b/lib/modem.js +@@ -3,7 +3,6 @@ var querystring = require('querystring'), + fs = require('fs'), + path = require('path'), + url = require('url'), +- ssh = require('./ssh'), + HttpDuplex = require('./http_duplex'), + debug = require('debug')('modem'), + utils = require('./utils'), +@@ -263,8 +262,13 @@ Modem.prototype.buildRequest = function (options, context, data, callback) { + var connectionTimeoutTimer; + var finished = false; + ++ // Loaded here rather than at module scope: './ssh' pulls in ssh2, whose crypto module ++ // instantiates a ~16 MiB WebAssembly memory for ChaCha20-Poly1305 as soon as it is ++ // required. Measured at +14 MiB RSS for a require alone, paid by every Homarr install ++ // even though Docker is reached over a socket and this branch never runs. require() is ++ // cached, so SSH connections pay it once and behave exactly as before. + var opts = self.protocol === 'ssh' ? Object.assign(options, { +- agent: ssh(Object.assign({}, self.sshOptions, { ++ agent: require('./ssh')(Object.assign({}, self.sshOptions, { + 'host': self.host, + 'port': self.port, + 'username': self.username, diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 0f31e95af..f863cb9be 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -585,6 +585,7 @@ overrides: patchedDependencies: '@types/node-unifi': 5e6ae51e2a17a7f9729bfa30b0eb3d0842a5810ac6db47603ab4a6efa1ed84c5 + docker-modem@5.0.7: 4a1c50dc8b726af921a34a77c4942a768bed229123ab116baa06c4e62ad6815c trpc-to-openapi: 2ca3c16af0fcca0c736697ad4fe553a14f794524fa9ce0d5c3e8ee4aea76090c importers: @@ -23646,7 +23647,7 @@ snapshots: dependencies: yaml: 2.9.0 - docker-modem@5.0.7(supports-color@10.2.2): + docker-modem@5.0.7(patch_hash=4a1c50dc8b726af921a34a77c4942a768bed229123ab116baa06c4e62ad6815c)(supports-color@10.2.2): dependencies: debug: 4.4.3(supports-color@10.2.2) readable-stream: 3.6.2 @@ -23660,7 +23661,7 @@ snapshots: '@balena/dockerignore': 1.0.2 '@grpc/grpc-js': 1.12.5 '@grpc/proto-loader': 0.7.13 - docker-modem: 5.0.7(supports-color@10.2.2) + docker-modem: 5.0.7(patch_hash=4a1c50dc8b726af921a34a77c4942a768bed229123ab116baa06c4e62ad6815c)(supports-color@10.2.2) protobufjs: 7.4.0 tar-fs: 2.1.4 transitivePeerDependencies: diff --git a/pnpm-workspace.yaml b/pnpm-workspace.yaml index d6e554ed6..44cf3977a 100644 --- a/pnpm-workspace.yaml +++ b/pnpm-workspace.yaml @@ -233,6 +233,7 @@ overrides: "vite@>=5.0.0 <=5.4.18": ">=8.1.4" patchedDependencies: "@types/node-unifi": "patches/@types__node-unifi.patch" + docker-modem@5.0.7: patches/docker-modem@5.0.7.patch "trpc-to-openapi": "patches/trpc-to-openapi.patch" allowUnusedPatches: true diff --git a/scripts/benchmarks/analyze-allocations.mjs b/scripts/benchmarks/analyze-allocations.mjs new file mode 100644 index 000000000..b50073085 --- /dev/null +++ b/scripts/benchmarks/analyze-allocations.mjs @@ -0,0 +1,99 @@ +// Reports what allocated memory during a stress run, by site and by owner — and, given two +// stages, what a single stage allocated. +// +// node scripts/benchmarks/analyze-allocations.mjs [fromStage] [toStage] +// node scripts/benchmarks/analyze-allocations.mjs .bench/stress/peak nav-03 07-multi-tab +// +// This is the counterpart to a heap snapshot and answers the opposite question. A snapshot is +// taken after a forced GC, so it shows only what *survived*; the churn that produces a memory +// peak is by definition gone by then. The sampling heap profiler records an allocation stack +// every N bytes regardless of survival, so a peak driven by transient garbage — which is what +// this container's peak turned out to be — shows up here and nowhere else. +// +// Sampling totals are cumulative since boot, so a single stage is only meaningful as the +// difference between two captures. Without stage arguments this reports the cumulative +// profile, which is dominated by boot-time module loading. +import { readFileSync, existsSync } from "node:fs"; +import path from "node:path"; + +const [, , directory, fromStage, toStage] = process.argv; +if (!directory) throw new Error("usage: analyze-allocations.mjs [fromStage] [toStage]"); + +const load = (stage) => { + const file = path.join(directory, `${stage}.allocations.json`); + if (!existsSync(file)) throw new Error(`missing ${file}`); + const parsed = JSON.parse(readFileSync(file, "utf8")); + if (parsed.disabled) throw new Error("sampling was not enabled (HOMARR_PROBE_SAMPLE_ALLOCATIONS)"); + return parsed; +}; + +const MiB = (bytes) => (bytes / 1048576).toFixed(2); + +/** Groups a frame to something a developer could act on: a package, a chunk, or node itself. */ +const ownerOf = (key) => { + const url = key.slice(key.indexOf("|") + 1); + if (!url || url.startsWith("undefined")) return "unattributed (no script)"; + if (/^node:/.test(url)) { + if (/cjs\/loader|modules\//.test(url)) return "node: CommonJS module loader (reading source)"; + return "node internals"; + } + const dependency = /\/app\/node_modules\/((?:@[^/]+\/)?[^/]+)\//.exec(url); + if (dependency) return `node_modules: ${dependency[1]}`; + if (url.includes("/.next/server/chunks/")) { + const chunk = /chunks\/(?:ssr\/)?([^/:]+)/.exec(url); + return `chunk ${chunk ? chunk[1] : "?"}`; + } + if (url.includes("/.next/server/app/")) return "route bundle"; + if (url.includes("/probe/")) return "the probe itself (diagnostics)"; + return "other"; +}; + +const shorten = (key) => + key.replace("|", " <- ").replace("/app/apps/nextjs/.next/server/", "").replace("/app/node_modules/", ""); + +let label; +let total; +let sites; + +if (fromStage && toStage) { + const before = load(fromStage); + const after = load(toStage); + const previous = new Map(before.sites.map((site) => [site.key, site.bytes])); + label = `allocated between "${fromStage}" and "${toStage}"`; + total = after.total - before.total; + sites = after.sites + .map((site) => ({ ...site, bytes: site.bytes - (previous.get(site.key) ?? 0) })) + .filter((site) => site.bytes > 0) + .sort((a, b) => b.bytes - a.bytes); +} else { + const profile = load(fromStage ?? "06-final"); + label = `cumulative since boot (${fromStage ?? "06-final"})`; + total = profile.total; + sites = profile.sites; +} + +const covered = sites.reduce((sum, site) => sum + site.bytes, 0); +console.log(`${label}: ${MiB(total)} MiB total, ${MiB(covered)} MiB attributed across ${sites.length} sites\n`); + +const byOwner = new Map(); +for (const site of sites) { + const owner = ownerOf(site.key); + const acc = byOwner.get(owner) ?? { bytes: 0, sites: 0 }; + acc.bytes += site.bytes; + acc.sites++; + byOwner.set(owner, acc); +} + +console.log("=== allocation volume by owner ==="); +console.log(`${"MiB".padStart(9)} ${"share".padStart(7)} ${"sites".padStart(6)} owner`); +for (const [owner, acc] of [...byOwner.entries()].sort((a, b) => b[1].bytes - a[1].bytes).slice(0, 18)) { + const share = covered === 0 ? "-" : `${((acc.bytes / covered) * 100).toFixed(1)}%`; + console.log(`${MiB(acc.bytes).padStart(9)} ${share.padStart(7)} ${String(acc.sites).padStart(6)} ${owner}`); +} + +console.log(`\n=== top individual allocation sites ===`); +for (const site of sites.slice(0, 16)) { + const share = covered === 0 ? "-" : `${((site.bytes / covered) * 100).toFixed(1)}%`; + console.log(`\n ${MiB(site.bytes)} MiB (${share}) ${shorten(site.key).slice(0, 110)}`); + for (const frame of (site.stack ?? []).slice(1, 4)) console.log(` from ${shorten(frame).slice(0, 106)}`); +} diff --git a/scripts/benchmarks/analyze-heap-dominators.mjs b/scripts/benchmarks/analyze-heap-dominators.mjs index d977087f4..fac8b070e 100644 --- a/scripts/benchmarks/analyze-heap-dominators.mjs +++ b/scripts/benchmarks/analyze-heap-dominators.mjs @@ -198,6 +198,17 @@ const label = (o) => { return `${type}:${name}`; }; +/** The property name a parent reaches a child through — that is what names the contents. */ +const edgeLabelBetween = (from, to) => { + for (let e = firstEdge[from]; e < firstEdge[from + 1]; e++) { + if (edges[e * eStride + eTo] / nStride !== to) continue; + const type = edgeTypes[edges[e * eStride + eType]]; + const raw = edges[e * eStride + eName]; + return type === "element" || type === "hidden" ? `[${raw}]` : (strings[raw] ?? String(raw)); + } + return "(indirect)"; +}; + const candidates = []; for (let i = 0; i < reachableCount; i++) { if (i === rootPost) continue; @@ -228,6 +239,26 @@ for (const i of candidates) { if (shown.length >= topN) break; } +// Expanding the single largest retainer is usually the whole point: "a Context retains 16 MiB" +// is not actionable until its contents are named. Only the dominator tree can do this — a +// plain graph walk escapes through __proto__ into the entire heap and reports nonsense. +if (shown.length) { + const top = shown[0]; + const childrenOfTop = []; + for (let i = 0; i < reachableCount; i++) { + if (i !== top && dom[i] === top) childrenOfTop.push(i); + } + childrenOfTop.sort((a, b) => retained[b] - retained[a]); + const topNode = postOrderNodes[top]; + console.log(`\n=== inside the largest retainer (${label(topNode)}, ${MiB(retained[top])} MiB) ===`); + console.log(` it dominates ${childrenOfTop.length} direct children; heaviest:`); + for (const child of childrenOfTop.slice(0, 20)) { + const node = postOrderNodes[child]; + const edgeName = edgeLabelBetween(topNode, node); + console.log(` ${MiB(retained[child]).padStart(8)} MiB ${edgeName} -> ${label(node).slice(0, 78)}`); + } +} + // Grouping by constructor over retained size shows which *kind* of thing dominates, which // is what a shallow histogram cannot express. const byName = new Map(); diff --git a/scripts/benchmarks/analyze-smaps-stages.mjs b/scripts/benchmarks/analyze-smaps-stages.mjs new file mode 100644 index 000000000..4e9f183df --- /dev/null +++ b/scripts/benchmarks/analyze-smaps-stages.mjs @@ -0,0 +1,121 @@ +// Breaks each stage's RSS into JS heap, JIT code, native malloc and file-backed pages. +// +// node scripts/benchmarks/analyze-smaps-stages.mjs .bench/stress/