mirror of
https://github.com/MBombeck/HealthLog.git
synced 2026-11-08 20:42:43 +00:00
fix(heap): report again at 95 % and leave a report on an out-of-memory exit
The pressure report re-armed only after the heap fell under 70 % and half an hour passed, so a heap that climbed to its limit soon after an 85 % report died with only that older report on record. A 95 % tier now writes the same report at once, whatever the cooldown, and re-arms under 85 %. The image sets NODE_OPTIONS so Node writes its diagnostic report to stderr when the heap runs out, with environment variables and network interfaces excluded. The heap-diagnostics and scaling docs say how to keep the flags when overriding NODE_OPTIONS. Heap figures share one megabytes helper with the support report.
This commit is contained in:
1 parent
3cf67d05f9
commit
b79bd8370d
7 files changed
+101
-14
No files matched your search
@@ -76,6 +76,15 @@ ENV NODE_ENV=production
|
||||
ENV NEXT_TELEMETRY_DISABLED=1
|
||||
ENV TZ=Europe/Berlin
|
||||
|
||||
# When the heap runs out, Node writes a diagnostic report (the JavaScript
|
||||
# and native stacks, heap spaces, libuv handles) to stderr, where
|
||||
# `docker compose logs` and Loki keep it; without it the log holds one
|
||||
# line. Environment variables and network interfaces are left out, so no
|
||||
# key, password or address from the environment reaches the log. An
|
||||
# operator who sets NODE_OPTIONS replaces this value and should carry these
|
||||
# flags over (docs/ops/heap-diagnostics.md).
|
||||
ENV NODE_OPTIONS="--report-on-fatalerror --report-filename=stderr --report-exclude-env --report-exclude-network"
|
||||
|
||||
# v1.4.43 B11 — forward NEXT_PUBLIC_APP_VERSION from the builder stage
|
||||
# into the runner so /api/version reads the build-arg value instead of
|
||||
# the package.json fallback. The variable is keyed to the CI tag ref
|
||||
|
||||
@@ -7,7 +7,7 @@ A Node process that reaches its heap limit stops with `JavaScript heap out of me
|
||||
Two background wide events, no configuration needed:
|
||||
|
||||
- `runtime.heap.sampled` (info), every five minutes, and every minute while the heap is at or above 70 % of its limit. It goes to stdout and Loki but not to Admin > App logs, so it cannot push other events out of that page's 500-entry buffer. It carries `heap_used_mb`, `heap_total_mb`, `heap_limit_mb`, `heap_used_ratio`, `old_space_mb`, `rss_mb`, `external_mb`, `array_buffers_mb`, `active_requests`, `active_jobs`, `in_flight_dropped` and `uptime_s`.
|
||||
- `runtime.heap.pressure` (warn), the first time the heap reaches 85 % of its limit. Besides the figures above it lists the 50 oldest requests and jobs in flight (`in_flight_oldest`: kind, method, route, age in seconds, whether it was a server action) and the routes most of them share (`in_flight_by_route`). Routes are reduced to their shape: no query string, secret path segments replaced by `[REDACTED]`, ids by `:id`, anything unusual by `:x`. It writes again only after the heap has dropped below 70 % and thirty minutes have passed.
|
||||
- `runtime.heap.pressure` (warn), the first time the heap reaches 85 % of its limit. Besides the figures above it lists the 50 oldest requests and jobs in flight (`in_flight_oldest`: kind, method, route, age in seconds, whether it was a server action) and the routes most of them share (`in_flight_by_route`). Routes are reduced to their shape: no query string, secret path segments replaced by `[REDACTED]`, ids by `:id`, anything unusual by `:x`. It writes again only after the heap has dropped below 70 % and thirty minutes have passed. One exception: when the heap reaches 95 %, the same report is written again at once, with `pressure_ratio: 0.95`, whatever the cooldown; that tier re-arms as soon as the heap is back under 85 %. A heap that climbs to its limit shortly after an 85 % report therefore still leaves a report naming the work that pushed it over.
|
||||
|
||||
The heap is read every five seconds, a single call that takes microseconds. Tracking requests costs one map insert and one delete per request.
|
||||
|
||||
@@ -17,6 +17,16 @@ To find the last lines before a crash:
|
||||
docker compose logs app --since 2h | grep '"runtime.heap.'
|
||||
```
|
||||
|
||||
## The report Node writes when the heap runs out
|
||||
|
||||
The image sets `NODE_OPTIONS="--report-on-fatalerror --report-filename=stderr --report-exclude-env --report-exclude-network"`. When the process runs out of heap, Node writes a diagnostic report, about 10 KB of JSON with `"trigger": "OOMError"`, to stderr just before it exits: the JavaScript stack at the failed allocation, the native stack, the heap spaces and the open handles. It lands in the container log beside the `runtime.heap.*` lines:
|
||||
|
||||
```sh
|
||||
docker compose logs app --since 2h | grep -A400 '"trigger": "OOMError"'
|
||||
```
|
||||
|
||||
The two exclude flags keep environment variables (keys, passwords, the database URL) and network interfaces out of the report. If you set `NODE_OPTIONS` yourself, for example to raise `--max-old-space-size`, your value replaces the image's; add the four flags to it to keep the report.
|
||||
|
||||
## Optional heap snapshot
|
||||
|
||||
A snapshot shows what the heap is made of, which the events above cannot. Turn it on only while you are chasing a specific crash:
|
||||
|
||||
@@ -79,9 +79,13 @@ Raise the limit on the container that runs the worker and re-upload:
|
||||
services:
|
||||
app:
|
||||
environment:
|
||||
NODE_OPTIONS: --max-old-space-size=1024
|
||||
NODE_OPTIONS: --max-old-space-size=1024 --report-on-fatalerror --report-filename=stderr --report-exclude-env --report-exclude-network
|
||||
```
|
||||
|
||||
Your `NODE_OPTIONS` replaces the image's, so carry the four `--report-*`
|
||||
flags over: they make an out-of-memory exit leave a diagnostic report in
|
||||
the container log (see `docs/ops/heap-diagnostics.md`).
|
||||
|
||||
An import interrupted by a container restart or an out-of-memory kill
|
||||
does not stay stuck: the worker reconciles non-terminal import jobs at
|
||||
boot and every 15 minutes, flipping orphaned rows to `failed`
|
||||
|
||||
@@ -23,7 +23,9 @@ import { walkSourceFiles } from "@/__tests__/helpers/source-files";
|
||||
|
||||
import {
|
||||
HEAP_CHECK_INTERVAL_MS,
|
||||
HEAP_CRITICAL_RATIO,
|
||||
HEAP_PRESSURE_COOLDOWN_MS,
|
||||
HEAP_PRESSURE_RATIO,
|
||||
HEAP_PRESSURE_LIST_MAX,
|
||||
HEAP_SAMPLE_INTERVAL_ELEVATED_MS,
|
||||
HEAP_SAMPLE_INTERVAL_MS,
|
||||
@@ -175,6 +177,41 @@ describe("heap pressure report", () => {
|
||||
expect(h.named(HEAP_TASK_NAMES.pressure)).toHaveLength(2);
|
||||
});
|
||||
|
||||
it("reports again at 95 % inside the cooldown, once per climb", () => {
|
||||
const h = harness();
|
||||
h.state.used = 900;
|
||||
h.run(60_000);
|
||||
// Ten minutes later, well inside the cooldown, the heap nears its limit.
|
||||
h.state.used = 800;
|
||||
h.run(10 * 60_000);
|
||||
h.state.used = 960;
|
||||
h.run(60_000);
|
||||
const pressure = h.named(HEAP_TASK_NAMES.pressure);
|
||||
expect(pressure.map((p) => p.meta.pressure_ratio)).toEqual([
|
||||
HEAP_PRESSURE_RATIO,
|
||||
HEAP_CRITICAL_RATIO,
|
||||
]);
|
||||
expect(pressure[1].meta).toHaveProperty("in_flight_oldest");
|
||||
|
||||
// Hovering at 95 % writes nothing more; back under 85 % re-arms it.
|
||||
h.run(5 * 60_000);
|
||||
expect(h.named(HEAP_TASK_NAMES.pressure)).toHaveLength(2);
|
||||
h.state.used = 840;
|
||||
h.run(HEAP_CHECK_INTERVAL_MS);
|
||||
h.state.used = 970;
|
||||
h.run(HEAP_CHECK_INTERVAL_MS);
|
||||
expect(h.named(HEAP_TASK_NAMES.pressure)).toHaveLength(3);
|
||||
});
|
||||
|
||||
it("writes one report at the tier a sudden jump reaches", () => {
|
||||
const h = harness();
|
||||
h.state.used = 990;
|
||||
h.run(60_000);
|
||||
const pressure = h.named(HEAP_TASK_NAMES.pressure);
|
||||
expect(pressure).toHaveLength(1);
|
||||
expect(pressure[0].meta.pressure_ratio).toBe(HEAP_CRITICAL_RATIO);
|
||||
});
|
||||
|
||||
it("writes no snapshot unless opted in, and at most one when it is", () => {
|
||||
const off = harness();
|
||||
off.state.used = 900;
|
||||
|
||||
@@ -9,6 +9,7 @@ import {
|
||||
import { envFlag, envOr } from "@/lib/env";
|
||||
import { WideEventBuilder } from "@/lib/logging/event-builder";
|
||||
import { emitIfSampled } from "@/lib/logging/transports";
|
||||
import { megabytes } from "@/lib/support/heap-limit";
|
||||
|
||||
import { inFlightRegistry, type InFlightRegistry } from "./in-flight";
|
||||
|
||||
@@ -32,7 +33,11 @@ import { inFlightRegistry, type InFlightRegistry } from "./in-flight";
|
||||
* flight and the routes most of them share (see `in-flight.ts`). It
|
||||
* re-arms only after the heap has fallen back under 70 % AND thirty minutes
|
||||
* have passed, so a heap hovering at the line writes one report, not one
|
||||
* every check.
|
||||
* every check. A second tier at 95 % writes the same report with no
|
||||
* cooldown at all, and re-arms as soon as the heap is back under 85 %:
|
||||
* a heap that climbs to its limit within the half hour after an 85 %
|
||||
* report would otherwise die with only that older report on record, the
|
||||
* requests that pushed it over missing from it.
|
||||
* - `runtime.heap.snapshot`, at `warn`, only with the opt-in below: where
|
||||
* the snapshot was written, or that writing it failed.
|
||||
*
|
||||
@@ -63,6 +68,7 @@ export const HEAP_SAMPLE_INTERVAL_MS = 5 * 60_000;
|
||||
export const HEAP_SAMPLE_INTERVAL_ELEVATED_MS = 60_000;
|
||||
export const HEAP_ELEVATED_RATIO = 0.7;
|
||||
export const HEAP_PRESSURE_RATIO = 0.85;
|
||||
export const HEAP_CRITICAL_RATIO = 0.95;
|
||||
export const HEAP_PRESSURE_COOLDOWN_MS = 30 * 60_000;
|
||||
export const HEAP_PRESSURE_LIST_MAX = 50;
|
||||
|
||||
@@ -101,10 +107,6 @@ export interface HeapMonitorDeps {
|
||||
writeSnapshot: () => SnapshotOutcome;
|
||||
}
|
||||
|
||||
function megabytes(bytes: number): number {
|
||||
return Math.round(bytes / 1024 / 1024);
|
||||
}
|
||||
|
||||
function defaultReadHeap(): { used: number; limit: number } {
|
||||
const stats = getHeapStatistics();
|
||||
return { used: stats.used_heap_size, limit: stats.heap_size_limit };
|
||||
@@ -205,6 +207,7 @@ export function writeDiagnosticHeapSnapshot(): SnapshotOutcome {
|
||||
export class HeapMonitor {
|
||||
private lastSampleAt: number | null = null;
|
||||
private pressureArmed = true;
|
||||
private criticalArmed = true;
|
||||
private lastPressureAt: number | null = null;
|
||||
private snapshotTaken = false;
|
||||
|
||||
@@ -225,11 +228,29 @@ export class HeapMonitor {
|
||||
this.pressureArmed = true;
|
||||
}
|
||||
|
||||
if (!this.criticalArmed && ratio < HEAP_PRESSURE_RATIO) {
|
||||
this.criticalArmed = true;
|
||||
}
|
||||
|
||||
if (this.pressureArmed && ratio >= HEAP_PRESSURE_RATIO) {
|
||||
this.pressureArmed = false;
|
||||
this.lastPressureAt = at;
|
||||
this.lastSampleAt = at;
|
||||
this.reportPressure(at);
|
||||
// A heap that jumps straight past 95 % gets one report, at the tier
|
||||
// it reached.
|
||||
const critical = ratio >= HEAP_CRITICAL_RATIO;
|
||||
if (critical) this.criticalArmed = false;
|
||||
this.reportPressure(
|
||||
at,
|
||||
critical ? HEAP_CRITICAL_RATIO : HEAP_PRESSURE_RATIO,
|
||||
);
|
||||
return;
|
||||
}
|
||||
|
||||
if (this.criticalArmed && ratio >= HEAP_CRITICAL_RATIO) {
|
||||
this.criticalArmed = false;
|
||||
this.lastSampleAt = at;
|
||||
this.reportPressure(at, HEAP_CRITICAL_RATIO);
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -245,7 +266,7 @@ export class HeapMonitor {
|
||||
}
|
||||
}
|
||||
|
||||
private reportPressure(at: number): void {
|
||||
private reportPressure(at: number, tier: number): void {
|
||||
const { registry, emit, readFigures } = this.deps;
|
||||
const inFlight = registry.report(at, HEAP_PRESSURE_LIST_MAX);
|
||||
const willSnapshot = this.deps.snapshotEnabled && !this.snapshotTaken;
|
||||
@@ -253,7 +274,7 @@ export class HeapMonitor {
|
||||
// process over, the report is already on stdout.
|
||||
emit(HEAP_TASK_NAMES.pressure, "warn", {
|
||||
...readFigures(),
|
||||
pressure_ratio: HEAP_PRESSURE_RATIO,
|
||||
pressure_ratio: tier,
|
||||
in_flight_oldest: inFlight.oldest,
|
||||
in_flight_by_route: inFlight.by_route,
|
||||
snapshot: willSnapshot ? "pending" : "disabled",
|
||||
|
||||
@@ -14,9 +14,14 @@ import { getHeapStatistics } from "node:v8";
|
||||
/** Below this, the heap is flagged. Between the 1g (524) and 1536m (792) heaps. */
|
||||
export const LOW_HEAP_LIMIT_MB = 700;
|
||||
|
||||
/** Bytes as whole megabytes (MiB), the unit every heap figure is shown in. */
|
||||
export function megabytes(bytes: number): number {
|
||||
return Math.round(bytes / 1024 / 1024);
|
||||
}
|
||||
|
||||
/** V8's heap limit for this process, in megabytes. */
|
||||
export function heapLimitMb(): number {
|
||||
return Math.round(getHeapStatistics().heap_size_limit / 1024 / 1024);
|
||||
return megabytes(getHeapStatistics().heap_size_limit);
|
||||
}
|
||||
|
||||
export function isHeapLimitLow(limitMb: number): boolean {
|
||||
|
||||
@@ -25,6 +25,7 @@ import {
|
||||
heapLimitMb,
|
||||
isHeapLimitLow,
|
||||
lowHeapLimitAdvice,
|
||||
megabytes,
|
||||
} from "@/lib/support/heap-limit";
|
||||
import { shouldEmitSecureCookie } from "@/lib/auth/secure-cookie";
|
||||
import { isOidcConfigured, isOidcOnly } from "@/lib/auth/oidc";
|
||||
@@ -692,8 +693,8 @@ function or(value: string | number | null | undefined, fallback = "unknown") {
|
||||
: String(value);
|
||||
}
|
||||
|
||||
function megabytes(bytes: number | null): string {
|
||||
return bytes === null ? "unknown" : `${Math.round(bytes / 1024 / 1024)} MB`;
|
||||
function sizeLine(bytes: number | null): string {
|
||||
return bytes === null ? "unknown" : `${megabytes(bytes)} MB`;
|
||||
}
|
||||
|
||||
function runLine(run: QueueRunFact | null): string {
|
||||
@@ -741,7 +742,7 @@ export function renderSupportReport(facts: SupportReportFacts): string {
|
||||
section("Database");
|
||||
row("PostgreSQL", facts.database.version);
|
||||
row("Server time zone", facts.database.timezone);
|
||||
row("Size", megabytes(facts.database.sizeBytes));
|
||||
row("Size", sizeLine(facts.database.sizeBytes));
|
||||
row(
|
||||
"Last migration",
|
||||
facts.database.lastMigration
|
||||
|
||||
Reference in new issue
Block a user