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

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';
@@ -99,6 +100,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.53.0",
+	"version": "0.54.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, max: 2147483647 }
+			),
 			enabled: option(
 				true,
 				'Serve the management API (and therefore anything the console can show).',
@@ -1525,6 +1537,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

@@ -709,6 +709,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 });

packages/plugin/test/eventLoopLag.test.js

@@ -0,0 +1,37 @@
+import { test } from 'node:test';
+import assert from 'node:assert/strict';
+
+/**
+ * `readLag` only, which is the part with a failure mode worth a test.
+ *
+ * The monitor around it is a libuv histogram plus a `setInterval`; exercising that would test node,
+ * not this. What is worth pinning is that an EMPTY window cannot emit `Infinity`: `recordAnalytics`
+ * aggregates by mean, so a single `Infinity` makes the merged row's mean `Infinity` for that period
+ * across every worker — the series reads as catastrophic while nothing is wrong, and it is the sort
+ * of thing that gets discovered from a dashboard weeks later.
+ */
+const { readLag } = await import('../src/util/eventLoopLag.js');
+
+const fake = (p99ns, maxns) => ({ percentile: () => p99ns, max: maxns });
+
+test('readLag converts nanoseconds to ms', () => {
+	assert.deepEqual(readLag(fake(12_000_000, 53_000_000)), { p99: 12, max: 53 });
+});
+
+test('an empty window emits NOTHING rather than Infinity', () => {
+	// What node actually returns for a histogram with no samples.
+	assert.deepEqual(readLag(fake(Infinity, Infinity)), {});
+	// And the mixed case: a max but no percentile, or the reverse, each drops only the bad half.
+	assert.deepEqual(readLag(fake(Infinity, 8_000_000)), { max: 8 });
+	assert.deepEqual(readLag(fake(4_000_000, Infinity)), { p99: 4 });
+});
+
+test('NaN is dropped too, not emitted as a reading', () => {
+	assert.deepEqual(readLag(fake(NaN, NaN)), {});
+});
+
+test('a zero-lag window is a real reading and must be kept', () => {
+	// Distinct from empty: libuv sampled and found no delay. Dropping it would make an idle worker
+	// indistinguishable from one whose monitor is broken.
+	assert.deepEqual(readLag(fake(0, 0)), { p99: 0, max: 0 });
+});

packages/plugin/test/readySweep.test.js

@@ -557,3 +557,29 @@ test('a due set that fills the cap is still reported truncated', async () => {
 	assert.equal(sweep.scanned, 25, 'read exactly the cap');
 	assert.equal(sweep.truncated, true, 'never reached a not-yet-due row, so the ordering is over a prefix');
 });
+
+test('the yield budget changes WHEN the walk pauses, never what it produces', async () => {
+	// The yield used to fire every 200 rows; it now fires on elapsed time. That is a change to
+	// scheduling, and the invariant worth pinning is that it is ONLY that — a sweep must publish the
+	// same set whether it pauses constantly or barely at all. A budget of 1ms yields on nearly every
+	// check at any realistic per-row cost; 1e9 never yields at all.
+	const rows = backlogWithLateHome();
+	const run = async (yieldBudget) => {
+		resetShared();
+		config.queue.ready.yieldBudget = yieldBudget;
+		seed(rows);
+		const sweep = await funnel.sweepReadySet({ nowMs: T0 });
+		const pass = await funnel.claimSchedules({ grantLimit: 3 });
+		return { sweep, keys: pass.jobs.map((j) => j.cacheKey) };
+	};
+
+	const chatty = await run(1);
+	const never = await run(1_000_000_000);
+	config.queue.ready.yieldBudget = 2;
+
+	assert.equal(chatty.sweep.due, never.sweep.due);
+	assert.equal(chatty.sweep.scanned, never.sweep.scanned, 'the same rows are read either way');
+	assert.equal(chatty.sweep.published, never.sweep.published);
+	assert.deepEqual(chatty.keys, never.keys, 'and the same jobs are granted, in the same order');
+	assert.deepEqual(chatty.keys[0], 'https://www.kohls.com/|desktop', 'still the late homepage first');
+});