perf(plugin): yield the sweep on a time budget, and measure loop lag per worker

packages/plugin/METRICS.md

@@ -130,7 +130,7 @@ reasoning behind it.
 | `route_page_age` | ms      | route      | cacheStatus | deviceType | Served age per route, split by freshness state — the "should this TTL move" number.                                                                                                                                                                                                                                                                                                                                                                           |
 | `render`         | value   | series     | per-series  | per-series | The render fleet in one scan: `time_ms` (duration by statusCode × candidacy — renders/hour = concurrency ÷ time_ms) and `outcome` (counter by outcome × detail, exactly one per posted result — the render-failure alert).                                                                                                                                                                                                                                    |
 | `origin_fetch`   | ms      | statusCode | reason      | —          | Cost of every non-cache serve: origin latency + status, by why the cache didn't answer (miss/stale/skip/invalidated/bypass/blob-missing/blob-timeout/render-timeout).                                                                                                                                                                                                                                                                                         |
-| `prerender_ops`  | value   | series     | detail      | context    | Every low-volume ops signal in one scan: `unrouted` (class, bucket), `sitemap_*`, `serve_error`, `config_warnings`, `page_age_negative` (bot, device), `demand_*` (ladder decisions + `fast_fraction`/`fill`), `invalidation_error` (kind), `invalidation_reenqueue` (outcome, scope).                                                                                                                                                                        |
+| `prerender_ops`  | value   | series     | detail      | context    | Every low-volume ops signal in one scan: `unrouted` (class, bucket), `sitemap_*`, `serve_error`, `config_warnings`, `page_age_negative` (bot, device), `demand_*` (ladder decisions + `fast_fraction`/`fill`), `invalidation_error` (kind), `invalidation_reenqueue` (outcome, scope), `event_loop_lag` (statistic, **worker index**).                                                                                                                        |
 | `queue_health`   | value   | series     | result      | —          | Every queue signal in one scan: the snapshot gauges (`overdue`, `lease_occupancy`, `below_floor`, `below_floor_age_ms`, `floor_pin_age_ms`, `paused`), `claim_scan_ms` (per pass, method = granted/empty/capped), `claim_granted` (per claim, method = ready/index), `ready_sweep_ms` (per sweep, method = complete/capped), `ready_published`, `ready_cadence` (per sweep, method = carried/resolved), `reconcile_restored`/`reconcile_missing` (per sweep). |
 
 Notes that bite:
@@ -371,6 +371,7 @@ The catalog above is reference; this is the short list. "Sum across nodes" is im
 | `queue_health` `claim_granted` all `index`, none `ready`                            | Prioritisation is not engaging: the sweep is failing, the ready buffer could not be sized, or the set is always dry. The queue looks healthy in every other series because the ready set reorders a fixed amount of work and moves no total.                                                                                                                                                         |
 | `queue_health` `ready_sweep_ms` method `capped`                                     | The sweep hit `queue.ready.sweepCap` without reaching a not-yet-due row, so it is ordering the oldest part of the backlog only — the rows it skipped are the youngest, i.e. exactly the recently-due pages the ordering exists to protect.                                                                                                                                                           |
 | `queue_health` `ready_published` at 0 with a non-empty backlog                      | The sweep is running and finding nothing to publish. Check `queue.ready.capacity` was sizeable at boot (it is restart-scoped) and that the claim floor has not advanced past the due set.                                                                                                                                                                                                            |
+| `prerender_ops` `event_loop_lag` high on ONE worker only                            | That worker is doing something the others are not — for this plugin, `workerIndex 0` runs the ready-set sweep, the queue-status sync and the reconciler. Compare against `duration` (`path: p`) p99: a median and p95 flat across workers with p99 blown out 10-30x on a few is the signature of intermittent loop blocking. Lower `queue.ready.yieldBudget` if the sweep is the one.                |
 | `queue_health` `ready_cadence` still mostly `resolved` after a full cadence         | Rows are being filed without an `effectiveInterval`, so the sweep is scoring them against their ROUTE ceiling rather than their demand-ladder rung — a promoted page reads as up to 4x less overdue than it is. Expected to be all `resolved` on the first sweep after an upgrade and to cross over as rows re-render; if it does not, a writer is passing `null` or the corpus is not re-rendering. |
 | `origin_fetch` p95 or 5xx/`0` share rising                                          | Origin trouble that bots feel directly on every miss; a rising `render-timeout` share is renderNow falling back.                                                                                                                                                                                                                                                                                     |
 | `queue_health` `paused` = 1 beyond the expected window                              | A node's queue is paused longer than whoever paused it intended.                                                                                                                                                                                                                                                                                                                                     |

packages/plugin/extension.js

@@ -15,6 +15,7 @@ import {
 	seedOverrideFingerprint,
 	startOverrideWatch,
 } from './src/util/configOverride.js';
+import { startEventLoopLagMonitor } from './src/util/eventLoopLag.js';
 import { startQueueStatusSync, startReadySweep } from './src/resources/RenderQueue.js';
 import { startSitemapRefreshScheduler } from './src/resources/Sitemap.js';
 import { startScheduleReconciler } from './src/util/reconcile.js';
@@ -98,6 +99,10 @@ export async function handleApplication(scope) {
 	// Start background work now that config is applied. All are idempotent and
 	// self-gate by worker/node. The reconciler is deliberately NOT pinned to one node:
 	// every node repairs the schedule rows it owns (see util/reconcile.js).
+	// EVERY WORKER, deliberately unlike the rest of these. The others self-gate to `workerIndex === 0`;
+	// this one has to run everywhere, because its whole purpose is to tell the worker that sweeps apart
+	// from the fifteen that do not. See util/eventLoopLag.js.
+	startEventLoopLagMonitor();
 	startQueueStatusSync();
 	startReadySweep();
 	startSitemapRefreshScheduler();

packages/plugin/package.json

@@ -1,6 +1,6 @@
 {
 	"name": "@harperfast/prerender",
-	"version": "0.52.0",
+	"version": "0.53.0",
 	"type": "module",
 	"description": "Configurable Harper plugin for prerendering pages for bots and crawlers",
 	"license": "Apache-2.0",

packages/plugin/src/configSchema.js

@@ -457,6 +457,18 @@ export const configSchema = group('Prerender plugin configuration.', {
 			'except the login/session/index routes requires a `super_user`. The console UI consuming this ' +
 			'API is the separate `@harperfast/prerender-console` component.',
 		{
+			eventLoopLagInterval: option(
+				60_000,
+				'How often each worker reports its own event-loop delay, in ms. `0` disables it.\n\n' +
+					'Reported PER WORKER on purpose. Analytics rows are per-thread, so one worker standing out ' +
+					'against its peers localises a stall to whatever only that worker does — for this plugin the ' +
+					'ready-set sweep, the queue-status sync and the reconciler, all pinned to `workerIndex 0`. A ' +
+					'single cluster-wide number averages exactly that signal away.\n\n' +
+					'Cheap: the histogram samples in libuv at 20ms and the reporter is one timer per worker. It ' +
+					'emits two `prerender_ops` `event_loop_lag` rows per worker per window (p99 and max), so the ' +
+					'cost of shortening it is analytics rows, not runtime.',
+				{ min: 0 }
+			),
 			enabled: option(
 				true,
 				'Serve the management API (and therefore anything the console can show).',
@@ -1357,6 +1369,25 @@ export const configSchema = group('Prerender plugin configuration.', {
 						'of its own interval at the default.',
 					{ min: 1 }
 				),
+				yieldBudget: option(
+					2,
+					'Milliseconds the sweep may hold the event loop before yielding, in ms.\n\n' +
+						'THE SWEEP RUNS ON A WORKER THAT ALSO SERVES BOT TRAFFIC, so this is the knob that decides ' +
+						'how long a crawler request can sit behind it. It replaced a fixed "yield every 200 rows", ' +
+						'which was chosen when `bench/queue-index` measured a row at ~2.4us — 200 rows was ~0.5ms ' +
+						'of held loop, invisible beside a ~1.6ms cache hit. On the production corpus a row costs ' +
+						'~55us, so those same 200 rows held the loop ~11ms and every request landing in that slice ' +
+						'waited for it. A row count cannot express "do not stall a request"; a time budget can, and ' +
+						'it stays correct when the per-row cost moves.\n\n' +
+						'The default is set just above a cache hit (~1.6ms served), so a request delayed by the ' +
+						'sweep is delayed by about the time it would take to serve. Raising it trades crawler ' +
+						'latency for slightly fewer yields, which buys almost nothing: yielding measured free ' +
+						'(2.375 vs 2.387us/row at 20,000 rows). Lower it if `event_loop_lag` on the sweeping ' +
+						'worker is worse than the p99 you want for `duration` (`path: p`).\n\n' +
+						'Granularity is bounded by an internal 32-row check interval, so the actual slice lands ' +
+						'between this and roughly this plus 2ms on the current corpus.',
+					{ min: 1 }
+				),
 			}
 		),
 		claimScanCap: option(

packages/plugin/src/metrics.js

@@ -690,6 +690,22 @@ export const metrics = Object.freeze({
 	originFetch: (durationMs, statusCode, reason) =>
 		server.recordAnalytics(durationMs, 'origin_fetch', statusCode, reason, null),
 
+	/**
+	 * Event-loop delay for ONE worker over the last window, in ms — a prerender_ops series.
+	 *
+	 * EMITTED BY EVERY WORKER, not just the sweeping one, and that is the entire point. Analytics rows
+	 * are per-thread, so a fleet where one worker's lag stands out against fifteen others localises a
+	 * stall to whatever only that worker does — which for this plugin means the ready-set sweep, the
+	 * queue-status sync and the reconciler, all of which self-gate to `workerIndex === 0`. A single
+	 * cluster-wide number would average exactly that signal away.
+	 *
+	 * `detail` is the statistic (`p99`/`max`), `context` the worker index as a string. The worker index
+	 * is closed and small, so it is safe as a dimension — cardinality is a year-long cost and this is
+	 * the one place a per-thread identity is worth paying for.
+	 */
+	eventLoopLag: (ms, statistic, workerIndex) =>
+		server.recordAnalytics(ms, 'prerender_ops', 'event_loop_lag', statistic, String(workerIndex)),
+
 	/** A committed response whose body failed on the way out — a prerender_ops series. */
 	serveError: (kind) => server.recordAnalytics(true, 'prerender_ops', 'serve_error', kind, null),
 

packages/plugin/src/util/eventLoopLag.js

@@ -0,0 +1,89 @@
+/**
+ * PER-WORKER EVENT-LOOP DELAY, so a stall can be attributed instead of guessed at.
+ *
+ * WHY THIS EXISTS. The bot-facing `duration` (`path: 'p'`) metric showed, on the production fleet,
+ * a median and p95 identical across every worker (1.6ms / ~2.7ms) while five workers carried a p99
+ * of 13-53ms against 3.6-7.4ms elsewhere. Median flat, p95 flat, p99 blown out by 10-30x is the
+ * signature of intermittent event-loop blocking: it only touches the small share of requests that
+ * land inside a stall. The arithmetic said the ready-set sweep must cause ~11ms slices (200 rows at
+ * ~55us/row, before `queue.ready.yieldBudget` replaced the row count) — but the tail was broader
+ * than one worker, and the sweep self-gates to `workerIndex === 0`. So the shape was CONSISTENT with
+ * the sweep and could not be pinned on it, and the other candidates (queue-status sync, reconciler,
+ * sitemap refresh, GC) were indistinguishable from it in that data.
+ *
+ * Lag measured per worker separates them. Whatever only worker 0 does shows up only on worker 0.
+ *
+ * WHY `monitorEventLoopDelay` AND NOT A TIMER-DRIFT LOOP. The libuv-side histogram samples in C++
+ * at a fixed interval and costs nothing measurable, where the usual `setTimeout`-drift trick both
+ * competes for the loop it is measuring and misses any stall shorter than its own interval.
+ */
+import { monitorEventLoopDelay } from 'node:perf_hooks';
+import { config, onConfigApplied } from '../config.js';
+import { metrics } from '../metrics.js';
+
+const NS_PER_MS = 1e6;
+
+/** Node's ceiling for `setInterval`; past it the delay overflows and fires after 1ms. */
+const MAX_TIMER_MS = 2147483647;
+
+/**
+ * The two statistics for one window, in ms, with unusable readings dropped.
+ *
+ * EXTRACTED SO IT CAN BE TESTED, because the failure it guards is silent and fleet-wide. An empty
+ * histogram — a window in which libuv took no sample — returns `Infinity` from `percentile()` and
+ * `0`/`Infinity` from `max`. Emitting `Infinity` does not just add a bad row: `recordAnalytics`
+ * aggregates by mean, so one `Infinity` makes the mean of the merged row `Infinity` for that whole
+ * period, across every worker. The series would read as catastrophic while nothing was wrong.
+ *
+ * READ BEFORE RESET is the caller's job and equally load-bearing: the histogram is cumulative, so a
+ * window that never resets pins the p99 at the worst stall since boot and never recovers.
+ */
+export const readLag = (histogram) => {
+	const out = {};
+	const p99 = histogram.percentile(99) / NS_PER_MS;
+	const max = histogram.max / NS_PER_MS;
+	if (Number.isFinite(p99)) out.p99 = p99;
+	if (Number.isFinite(max)) out.max = max;
+	return out;
+};
+
+let started = false;
+
+/**
+ * Sample this worker's loop delay on an interval and report it.
+ *
+ * NOT gated to one worker, unlike every other periodic task here — see the module comment. Idempotent,
+ * and it follows `management.eventLoopLagInterval` without a restart.
+ */
+export function startEventLoopLagMonitor() {
+	if (started) return;
+	const interval = () => Math.max(0, config.management.eventLoopLagInterval | 0);
+	if (interval() <= 0) return;
+	started = true;
+
+	// `resolution` is how often libuv samples. 20ms is coarse enough to cost nothing and fine enough
+	// to catch a slice of the size this exists to look for; a stall shorter than one sample is, by
+	// construction, shorter than the thing being investigated.
+	const histogram = monitorEventLoopDelay({ resolution: 20 });
+	histogram.enable();
+
+	const report = () => {
+		// Read BEFORE reset — see `readLag`. Both halves matter and neither is obvious from the call.
+		const lag = readLag(histogram);
+		histogram.reset();
+		if (lag.p99 !== undefined) metrics.eventLoopLag(lag.p99, 'p99', server.workerIndex);
+		if (lag.max !== undefined) metrics.eventLoopLag(lag.max, 'max', server.workerIndex);
+	};
+
+	let armed = interval();
+	let timer = setInterval(report, Math.min(MAX_TIMER_MS, armed));
+	timer.unref?.();
+
+	onConfigApplied(() => {
+		if (interval() === armed) return;
+		clearInterval(timer);
+		armed = interval();
+		timer = armed > 0 ? setInterval(report, Math.min(MAX_TIMER_MS, armed)) : null;
+		timer?.unref?.();
+	});
+}

packages/plugin/src/util/renderSchedule.js

@@ -505,6 +505,13 @@ export const runClaimPass = async ({
  * they resolved a cadence differently the push distance would stop matching the number the row was
  * ranked by. `Number` first for the BigInt-from-`Long` coercion; `> 0` rejects null/NaN/negatives.
  */
+/**
+ * How often the walk consults the clock. Not a tuning knob — it only bounds the OVERSHOOT past the
+ * time budget: at ~55us/row, 32 rows is ~1.8ms of granularity, so a 2ms budget yields somewhere in
+ * 2-4ms. Lowering it buys precision nobody needs; raising it makes the budget a suggestion.
+ */
+const YIELD_CHECK_ROWS = 32;
+
 const carriedCadence = (effectiveInterval) => {
 	const ms = Number(effectiveInterval);
 	return Number.isFinite(ms) && ms > 0 ? ms : null;
@@ -739,6 +746,10 @@ export const sweepReadySet = async ({ nowMs = Date.now() } = {}) => {
 		return interval;
 	};
 
+	// Time budget for one uninterrupted slice of the walk. Read once per sweep: a live change applies
+	// to the next sweep, and re-reading config inside the loop is work per row for no benefit.
+	const yieldBudgetMs = Math.max(1, config.queue.ready.yieldBudget | 0);
+	let lastYieldAt = performance.now();
 	let scanned = 0;
 	let due = 0;
 	let nonFinite = 0;
@@ -825,9 +836,22 @@ export const sweepReadySet = async ({ nowMs = Date.now() } = {}) => {
 		const intervalMs = carried ?? intervalFor(CacheKey.extractUrl(row.cacheKey));
 		const score = scoreOf({ dueAt, fromSitemap: !!row.fromSitemap }, { nowMs, intervalMs, sitemapBoost });
 		heap.offer(score, { cacheKey: row.cacheKey, dueAt, fromSitemap: !!row.fromSitemap });
-		// Yielding is free (measured: 2.375 vs 2.387 us/row at 20,000 rows) and this runs beside bot
-		// traffic on a worker that also serves requests, so it must not hold the loop for a whole sweep.
-		if (scanned % 200 === 0) await yieldNow();
+		// YIELD ON ELAPSED TIME, NOT ON A ROW COUNT — and the difference is the whole point of this
+		// clause. It used to yield every 200 rows, chosen when `bench/queue-index` said a row cost
+		// ~2.4us: 200 rows was ~0.5ms of held loop, invisible next to a ~1.6ms cache hit. On the real
+		// corpus a row costs ~55us, so the same 200 rows hold the loop for ~11ms — and this worker also
+		// serves bot traffic, so every request landing inside that slice waits for it. A row count
+		// cannot express "do not stall a request"; a time budget can, and it re-derives itself when the
+		// per-row cost moves instead of needing a constant re-tuned by hand.
+		//
+		// The clock is read every `YIELD_CHECK_ROWS` rows rather than every row. `performance.now()` is
+		// tens of nanoseconds against ~55us of work, so per-row would be free TODAY — but the reason
+		// this clause is being rewritten at all is that a per-row cost moved 20x, and at 2.4us/row a
+		// per-row clock read would be ~2%. Sampling costs nothing and does not care.
+		if (scanned % YIELD_CHECK_ROWS === 0 && performance.now() - lastYieldAt >= yieldBudgetMs) {
+			await yieldNow();
+			lastYieldAt = performance.now();
+		}
 	}
 
 	const published = queue.publish(heap.drainDescending(), { scannedRows: scanned });