From 7431a1db2a8f66881b71c785a1bf136beab47cf7 Mon Sep 17 00:00:00 2001 From: Aleksandar Grbic Date: Fri, 29 May 2026 13:44:26 +0200 Subject: [PATCH] feat(observability): elevate Node event-loop signals to first-class MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Following Matteo Collina's longstanding point that event-loop lag / utilisation are the leading indicators for a Node service's health (CPU + memory don't tell you whether the loop can dispatch callbacks), promote both signals to the top of the API dashboard and add alert rules for the two failure modes that matter. apps/api/src/lib/metrics/event-loop-metrics.ts (new) - Custom Prometheus Gauge `nodejs_eventloop_utilization` (0.0–1.0) computed from `perf_hooks.performance.eventLoopUtilization()` on each `collect` call. - Snapshots the prior sample and diffs against it so the gauge reflects interval utilisation, not all-time average. - Self-registers on the shared metricsRegistry — imported via the metrics barrel; loaded by metrics.routes.ts on first hit. prometheus/rules.yml — three new alerts in boringstack-api - NodeEventLoopLagging (warn) — p99 lag > 200ms for 5min. Users feel added latency, time to investigate. - NodeEventLoopBlocked (page) — p99 lag > 1s for 2min. Service effectively unresponsive; requests queueing. - NodeEventLoopSaturated (warn) — ELU avg > 90% for 10min. No headroom; next traffic burst overflows. grafana/dashboards/boringstack-api.json — rewrite layout - New top stat row (y=0, h=5): ELU current %, event-loop lag p99, 5xx rate, total request rate. "Is the API healthy right now?" in one glance. - Row 2: request rate per route + request latency p95 per route (the previous top-row, demoted). - Row 3: event loop lag (p50 + p99 timeseries) + ELU over time — two side-by-side panels for "did the loop get worse, and when?" - Row 4: Memory (RSS + heap) + Process CPU + Requests by status. Why ELU matters alongside lag: lag tells you *how late* callbacks ran (a reactive signal — already feeling it). ELU tells you *how saturated* the loop is (a leading signal — the loop is keeping up *for now* but has no headroom). Verification: dashboard JSON validates; `promtool check rules` ok with 16 rules now (was 13); `bun run validate` 997 pass / 2 skip. Co-Authored-By: Claude Opus 4.7 --- .../api/src/lib/metrics/event-loop-metrics.ts | 41 +++ apps/api/src/lib/metrics/index.ts | 1 + .../grafana/dashboards/boringstack-api.json | 259 ++++++++++++++---- infra/compose/compose/prometheus/rules.yml | 58 ++++ 4 files changed, 304 insertions(+), 55 deletions(-) create mode 100644 apps/api/src/lib/metrics/event-loop-metrics.ts diff --git a/apps/api/src/lib/metrics/event-loop-metrics.ts b/apps/api/src/lib/metrics/event-loop-metrics.ts new file mode 100644 index 00000000..0307516c --- /dev/null +++ b/apps/api/src/lib/metrics/event-loop-metrics.ts @@ -0,0 +1,41 @@ +import { performance } from "node:perf_hooks"; +import { Gauge } from "prom-client"; + +import { metricsRegistry } from "./registry"; + +/* + * Event Loop Utilization (ELU). + * + * Matteo Collina's argument (and the wider Node.js community's): event + * loop lag is *the* leading indicator of a Node service's health, + * because CPU and memory don't tell you whether the loop can actually + * dispatch callbacks. Lag (already collected by `collectDefaultMetrics` + * as `nodejs_eventloop_lag_*_seconds`) measures *how late* callbacks + * run. ELU goes one step further: it measures *how saturated* the loop + * is, on a 0.0–1.0 scale. + * + * - 0.0 → loop idle (no JS executing, only waiting on I/O) + * - 0.5 → loop is busy half the time + * - 1.0 → loop is fully saturated, no headroom + * + * Sustained >0.9 means the next burst will tip you into queueing + * requests. Use as a paging signal alongside lag p99. + * + * `eventLoopUtilization()` is cumulative since process start; we diff + * against the previous sample on each scrape so the gauge reflects + * the *interval* utilisation, not the all-time average. + */ +let previousElu = performance.eventLoopUtilization(); + +export const nodejsEventLoopUtilization = new Gauge({ + name: "nodejs_eventloop_utilization", + help: "Event loop utilization since the previous scrape (0.0–1.0). >0.9 sustained = no headroom.", + registers: [metricsRegistry], + collect() { + const next = performance.eventLoopUtilization(previousElu); + + this.set(next.utilization); + + previousElu = performance.eventLoopUtilization(); + }, +}); diff --git a/apps/api/src/lib/metrics/index.ts b/apps/api/src/lib/metrics/index.ts index 2eb6243c..232b04dd 100644 --- a/apps/api/src/lib/metrics/index.ts +++ b/apps/api/src/lib/metrics/index.ts @@ -1,2 +1,3 @@ +export { nodejsEventLoopUtilization } from "./event-loop-metrics"; export { httpRequestDurationSeconds, httpRequestsTotal } from "./http-metrics"; export { metricsRegistry } from "./registry"; diff --git a/infra/compose/compose/grafana/dashboards/boringstack-api.json b/infra/compose/compose/grafana/dashboards/boringstack-api.json index 3dc55e93..f8cd22bb 100644 --- a/infra/compose/compose/grafana/dashboards/boringstack-api.json +++ b/infra/compose/compose/grafana/dashboards/boringstack-api.json @@ -12,13 +12,153 @@ } ] }, - "description": "BoringStack api: request rate, latency, error rate, and Node.js runtime health. Populated by the /metrics endpoint via prom-client.", + "description": "BoringStack API — health-at-a-glance stat row, RED panels per route, Node.js runtime detail. Event loop utilisation and lag are the first place to look for Node performance issues — they tell you whether the runtime can dispatch callbacks, which CPU and memory don't.", "editable": true, "fiscalYearStartMonth": 0, "graphTooltip": 0, "links": [], "liveNow": false, "panels": [ + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "description": "Event loop utilisation — fraction of time the loop is busy. >0.9 means no headroom. Single most important Node.js health signal.", + "fieldConfig": { + "defaults": { + "color": { "mode": "thresholds" }, + "thresholds": { + "mode": "absolute", + "steps": [ + { "color": "green", "value": null }, + { "color": "orange", "value": 0.7 }, + { "color": "red", "value": 0.9 } + ] + }, + "unit": "percentunit", + "min": 0, + "max": 1 + }, + "overrides": [] + }, + "gridPos": { "h": 5, "w": 6, "x": 0, "y": 0 }, + "id": 1, + "options": { + "colorMode": "background", + "graphMode": "area", + "reduceOptions": { "calcs": ["lastNotNull"], "fields": "", "values": false }, + "textMode": "value_and_name" + }, + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "expr": "avg(nodejs_eventloop_utilization{app=\"boringstack-api\"})", + "refId": "A" + } + ], + "title": "Event loop utilization", + "type": "stat" + }, + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "description": "How late the event loop is dispatching callbacks at p99. >200ms = users feel added latency. >1s = service effectively unresponsive.", + "fieldConfig": { + "defaults": { + "color": { "mode": "thresholds" }, + "thresholds": { + "mode": "absolute", + "steps": [ + { "color": "green", "value": null }, + { "color": "orange", "value": 0.05 }, + { "color": "red", "value": 0.2 } + ] + }, + "unit": "s" + }, + "overrides": [] + }, + "gridPos": { "h": 5, "w": 6, "x": 6, "y": 0 }, + "id": 2, + "options": { + "colorMode": "background", + "graphMode": "area", + "reduceOptions": { "calcs": ["lastNotNull"], "fields": "", "values": false }, + "textMode": "value_and_name" + }, + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "expr": "nodejs_eventloop_lag_p99_seconds{app=\"boringstack-api\"}", + "refId": "A" + } + ], + "title": "Event loop lag (p99)", + "type": "stat" + }, + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "thresholds" }, + "thresholds": { + "mode": "absolute", + "steps": [ + { "color": "green", "value": null }, + { "color": "orange", "value": 0.5 }, + { "color": "red", "value": 5 } + ] + }, + "unit": "reqps" + }, + "overrides": [] + }, + "gridPos": { "h": 5, "w": 6, "x": 12, "y": 0 }, + "id": 3, + "options": { + "colorMode": "background", + "graphMode": "area", + "reduceOptions": { "calcs": ["lastNotNull"], "fields": "", "values": false }, + "textMode": "value_and_name" + }, + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "expr": "sum(rate(http_requests_total{app=\"boringstack-api\",status=~\"5..\"}[5m]))", + "refId": "A" + } + ], + "title": "5xx error rate", + "type": "stat" + }, + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "fieldConfig": { + "defaults": { + "color": { "mode": "thresholds" }, + "thresholds": { + "mode": "absolute", + "steps": [{ "color": "blue", "value": null }] + }, + "unit": "reqps" + }, + "overrides": [] + }, + "gridPos": { "h": 5, "w": 6, "x": 18, "y": 0 }, + "id": 4, + "options": { + "colorMode": "background", + "graphMode": "area", + "reduceOptions": { "calcs": ["lastNotNull"], "fields": "", "values": false }, + "textMode": "value_and_name" + }, + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "expr": "sum(rate(http_requests_total{app=\"boringstack-api\"}[5m]))", + "refId": "A" + } + ], + "title": "Total request rate", + "type": "stat" + }, { "datasource": { "type": "prometheus", "uid": "prometheus" }, "fieldConfig": { @@ -36,8 +176,8 @@ }, "overrides": [] }, - "gridPos": { "h": 8, "w": 12, "x": 0, "y": 0 }, - "id": 1, + "gridPos": { "h": 8, "w": 12, "x": 0, "y": 5 }, + "id": 5, "options": { "legend": { "calcs": ["last", "max"], "displayMode": "table", "placement": "bottom", "showLegend": true }, "tooltip": { "mode": "multi", "sort": "desc" } @@ -70,8 +210,8 @@ }, "overrides": [] }, - "gridPos": { "h": 8, "w": 12, "x": 12, "y": 0 }, - "id": 2, + "gridPos": { "h": 8, "w": 12, "x": 12, "y": 5 }, + "id": 6, "options": { "legend": { "calcs": ["last", "max"], "displayMode": "table", "placement": "bottom", "showLegend": true }, "tooltip": { "mode": "multi", "sort": "desc" } @@ -89,60 +229,76 @@ }, { "datasource": { "type": "prometheus", "uid": "prometheus" }, + "description": "Event loop lag over time. Watch for sustained elevation or sharp spikes — both mean the loop is starving for execution slots.", "fieldConfig": { "defaults": { - "color": { "mode": "thresholds" }, - "mappings": [], - "thresholds": { - "mode": "absolute", - "steps": [ - { "color": "green", "value": null }, - { "color": "orange", "value": 1 }, - { "color": "red", "value": 5 } - ] + "color": { "mode": "palette-classic" }, + "custom": { + "axisLabel": "seconds", + "drawStyle": "line", + "fillOpacity": 10, + "lineWidth": 2, + "showPoints": "never", + "spanNulls": true }, - "unit": "reqps" + "unit": "s" }, - "overrides": [] + "overrides": [ + { + "matcher": { "id": "byName", "options": "p99" }, + "properties": [{ "id": "color", "value": { "mode": "fixed", "fixedColor": "red" } }] + }, + { + "matcher": { "id": "byName", "options": "p50" }, + "properties": [{ "id": "color", "value": { "mode": "fixed", "fixedColor": "orange" } }] + } + ] }, - "gridPos": { "h": 6, "w": 8, "x": 0, "y": 8 }, - "id": 3, + "gridPos": { "h": 7, "w": 12, "x": 0, "y": 13 }, + "id": 7, "options": { - "colorMode": "value", - "graphMode": "area", - "justifyMode": "auto", - "orientation": "auto", - "reduceOptions": { "calcs": ["lastNotNull"], "fields": "", "values": false }, - "textMode": "auto" + "legend": { "calcs": ["last", "max"], "displayMode": "table", "placement": "bottom", "showLegend": true }, + "tooltip": { "mode": "multi" } }, "targets": [ { "datasource": { "type": "prometheus", "uid": "prometheus" }, - "expr": "sum(rate(http_requests_total{app=\"boringstack-api\",status=~\"5..\"}[1m]))", + "expr": "nodejs_eventloop_lag_p99_seconds{app=\"boringstack-api\"}", + "legendFormat": "p99", "refId": "A" + }, + { + "datasource": { "type": "prometheus", "uid": "prometheus" }, + "expr": "nodejs_eventloop_lag_p50_seconds{app=\"boringstack-api\"}", + "legendFormat": "p50", + "refId": "B" } ], - "title": "5xx error rate", - "type": "stat" + "title": "Event loop lag (p50 + p99)", + "type": "timeseries" }, { "datasource": { "type": "prometheus", "uid": "prometheus" }, + "description": "Event loop utilisation over time. Sustained >0.9 means the next traffic burst will overflow into queued requests.", "fieldConfig": { "defaults": { - "color": { "mode": "palette-classic" }, + "color": { "mode": "fixed", "fixedColor": "purple" }, "custom": { + "axisLabel": "% busy", "drawStyle": "line", - "fillOpacity": 10, + "fillOpacity": 20, "lineWidth": 2, "showPoints": "never", "spanNulls": true }, - "unit": "bytes" + "unit": "percentunit", + "min": 0, + "max": 1 }, "overrides": [] }, - "gridPos": { "h": 6, "w": 8, "x": 8, "y": 8 }, - "id": 4, + "gridPos": { "h": 7, "w": 12, "x": 12, "y": 13 }, + "id": 8, "options": { "legend": { "calcs": ["last", "max"], "displayMode": "list", "placement": "bottom", "showLegend": true }, "tooltip": { "mode": "single" } @@ -150,18 +306,12 @@ "targets": [ { "datasource": { "type": "prometheus", "uid": "prometheus" }, - "expr": "process_resident_memory_bytes{app=\"boringstack-api\"}", - "legendFormat": "RSS", + "expr": "nodejs_eventloop_utilization{app=\"boringstack-api\"}", + "legendFormat": "ELU", "refId": "A" - }, - { - "datasource": { "type": "prometheus", "uid": "prometheus" }, - "expr": "nodejs_heap_size_used_bytes{app=\"boringstack-api\"}", - "legendFormat": "heap used", - "refId": "B" } ], - "title": "Memory (RSS + heap)", + "title": "Event loop utilization", "type": "timeseries" }, { @@ -170,19 +320,18 @@ "defaults": { "color": { "mode": "palette-classic" }, "custom": { - "axisLabel": "seconds", "drawStyle": "line", "fillOpacity": 10, "lineWidth": 2, "showPoints": "never", "spanNulls": true }, - "unit": "s" + "unit": "bytes" }, "overrides": [] }, - "gridPos": { "h": 6, "w": 8, "x": 16, "y": 8 }, - "id": 5, + "gridPos": { "h": 6, "w": 8, "x": 0, "y": 20 }, + "id": 9, "options": { "legend": { "calcs": ["last", "max"], "displayMode": "list", "placement": "bottom", "showLegend": true }, "tooltip": { "mode": "single" } @@ -190,18 +339,18 @@ "targets": [ { "datasource": { "type": "prometheus", "uid": "prometheus" }, - "expr": "nodejs_eventloop_lag_p99_seconds{app=\"boringstack-api\"}", - "legendFormat": "p99", + "expr": "process_resident_memory_bytes{app=\"boringstack-api\"}", + "legendFormat": "RSS", "refId": "A" }, { "datasource": { "type": "prometheus", "uid": "prometheus" }, - "expr": "nodejs_eventloop_lag_p50_seconds{app=\"boringstack-api\"}", - "legendFormat": "p50", + "expr": "nodejs_heap_size_used_bytes{app=\"boringstack-api\"}", + "legendFormat": "heap used", "refId": "B" } ], - "title": "Event-loop lag", + "title": "Memory (RSS + heap)", "type": "timeseries" }, { @@ -220,8 +369,8 @@ }, "overrides": [] }, - "gridPos": { "h": 6, "w": 12, "x": 0, "y": 14 }, - "id": 6, + "gridPos": { "h": 6, "w": 8, "x": 8, "y": 20 }, + "id": 10, "options": { "legend": { "calcs": ["last", "max"], "displayMode": "list", "placement": "bottom", "showLegend": true }, "tooltip": { "mode": "single" } @@ -255,8 +404,8 @@ }, "overrides": [] }, - "gridPos": { "h": 6, "w": 12, "x": 12, "y": 14 }, - "id": 7, + "gridPos": { "h": 6, "w": 8, "x": 16, "y": 20 }, + "id": 11, "options": { "legend": { "calcs": ["last"], "displayMode": "table", "placement": "bottom", "showLegend": true }, "tooltip": { "mode": "multi" } @@ -282,6 +431,6 @@ "timezone": "", "title": "BoringStack — API", "uid": "boringstack-api", - "version": 1, + "version": 2, "weekStart": "" } diff --git a/infra/compose/compose/prometheus/rules.yml b/infra/compose/compose/prometheus/rules.yml index 96a38524..665b8fe7 100644 --- a/infra/compose/compose/prometheus/rules.yml +++ b/infra/compose/compose/prometheus/rules.yml @@ -89,6 +89,64 @@ groups: for the api service. Verify the container is healthy and Traefik can reach it. + - alert: NodeEventLoopLagging + # Event loop lag p99 above 200ms means the loop is taking too + # long to dispatch callbacks — every request gets at least that + # much added latency on top of its own work. Common causes: + # sync FS calls, JSON.parse of large bodies, regex catastrophes, + # CPU-bound work outside a worker thread. + expr: | + nodejs_eventloop_lag_p99_seconds{app="boringstack-api"} > 0.2 + for: 5m + labels: + severity: warn + component: api + annotations: + summary: "Node event-loop lag p99 above 200ms for 5 minutes" + description: | + p99 callback dispatch lag is {{ $value | humanizeDuration }}. + The loop can't keep up — investigate via Grafana → API + dashboard (Event-loop lag panel) and the Tempo traces for + slow spans. Profile candidates: sync APIs, large JSON + payloads, CPU-bound paths that should move to a worker. + + - alert: NodeEventLoopBlocked + # p99 over 1 second means the service is effectively unresponsive + # to new work for noticeable stretches. Page immediately — at + # this point requests are queueing and users are seeing it. + expr: | + nodejs_eventloop_lag_p99_seconds{app="boringstack-api"} > 1 + for: 2m + labels: + severity: page + component: api + annotations: + summary: "Node event-loop lag p99 above 1s — service effectively blocked" + description: | + The Node runtime can't keep up with the work queued on the + event loop. Requests are stacking. Most likely a single + blocking operation hot path — `process.stack` / profiler / + `bun --inspect` to find it. + + - alert: NodeEventLoopSaturated + # ELU (event loop utilization) sustained above 90% means there's + # no headroom — the next burst of traffic tips you into queueing. + # Lag may still look fine if the loop is just keeping up. + expr: | + avg_over_time(nodejs_eventloop_utilization{app="boringstack-api"}[5m]) > 0.9 + for: 10m + labels: + severity: warn + component: api + annotations: + summary: "Node event-loop utilization above 90% for 10 minutes" + description: | + ELU is {{ $value | humanizePercentage }} over the last 5 + minutes. The loop is keeping up *for now* but has no + headroom. Either scale out, or find what's keeping the loop + busy via the Tempo trace waterfalls and refactor toward + async / worker threads. + - name: boringstack-database interval: 30s rules: