[ldt1996]

⊙ Problem

Core analytics cannot show one fully busy worker among idle ones. duration is summed across threads. Nothing records how late a thread's event loop runs. Requests in the HTTP request queue record no wait because duration starts at handler entry.

🤔 Is this still needed now that akamai-status reads event-loop utilization?

Yes. The component no longer depends on it, but per-thread lateness and queue wait are signals utilization cannot give: a loop can be busy without being late. Dawson wants them in Studio. Dropping the PR would only remove those signals.

💡 Solution

• event-loop-delay: one row per thread and period, how late a 20 ms timer fired, in milliseconds.
• duration-by-thread: one row per worker thread and period, with the count and mean of all its duration entries, in hdb_analytics only. duration rows are unchanged.
• request-time: dispatch to response ready, including the request-queue wait, for requests with a method other than GET, HEAD, and OPTIONS on Node and uWS. Bun, and a uWS request handed to Fastify, record none.
• Aggregate memory and queue-depth rows now carry the aggregation period, and no summed threadId.

⚖️ Alternatives

• A nested threads object on existing rows — the Grafana datasource has no case for an object attribute, and it would be the first in hdb_analytics.
• Extra duration rows with a thread attribute — every consumer that sums duration would count twice.
• The throttle's cycle-time estimate — it updates only while a call is queued.
• Stamping at the parser's message-begin callback — measured: it saw no event-loop wait, only the client's header time.

Framing-Verdict: chosen-approach-sound (530723b589cc)

🤔 Rows per thread, or a nested threads object?

Rows per thread, with a thread attribute like path and method. The nested form was requested, but Grafana's datasource cannot read an object attribute. Switching later means rewriting aggregateEntry and every consumer of the rows.

🔧 Changes

• server/eventLoopDelay.ts is new. It starts Node's sampler at 20 ms, and converts a reading to milliseconds past that interval.
• server/http.ts: a request bound for the request queue is stamped at dispatch while analytics is on, and request-time is recorded beside duration on the Node and uWS paths. Unqueued requests only find no stamp and skip the record.
• server/serverHelpers/requestTimePlugin.js records request-time for a stamped request handed to Fastify.
• resources/analytics/write.ts: the sampler starts on the first enabled check rather than at module load. The histogram resets at each flush and at a window's open only after an idle gap, at boot, or after analytics is turned back on. The flush runs one timer turn after its deadline, so a stall past the deadline is kept. Per-thread entries aggregate under a NUL-separated key. duration aggregates once per thread, so row counts grow with threads rather than paths. The byThread aggregation keeps period.
• resources/analytics/metadata.ts lists the three names as built-in metrics.
• Design notes: resources/analytics/DESIGN.md, server/DESIGN.md, and the root index.
• benchmarks/request-time/drive.mjs is the keep-alive driver, and benchmarks/request-time/README.md holds its numbers.

✅ Verification

• aggregationCycle.test.js, eventLoopDelay.test.js and requestTimePlugin.test.js pass 20 of 20 at 5e87ee7, under RocksDB and LMDB. The deadline-stall test fails on most runs of the old flush order, and the idle-gap test fails on the old window-open reset in every run.
• A live smoke at 5e87ee7 wrote one event-loop-delay and one duration-by-thread row per reporting thread, and request-time for PUT and POST but not GET.
• Keep-alive benchmarks on the Node, uWS and Fastify paths stay inside run-to-run noise against the merge base.
• No unit test drives the Node or uWS path end to end for request-time; the Fastify hook's test calls the hook with a supplied stamp, and the benchmark's queued runs produce the rows.
• PR QA: skipped @ 5e87ee7 — dispatch is not available to this session.

Docs companion: HarperFast/documentation#744.

Smoke rows, unedited

core 6639a076a
traffic: 40 PUT, 40 GET, 10 POST on /Probe
raw reports: 1; aggregate rows: 91
raw event-loop-delay: 1 entries, e.g. {"metric": "event-loop-delay", "threadId": 2, "perThread": true, "mean": 1.098317913043477, "maxDelay": 2.7082230000000003, "count": 46}
raw request-time: 2 entries, e.g. {"metric": "request-time", "path": "Probe", "method": "PUT", "mean": 0.36905937500002894, "count": 40}
raw duration-by-thread: none
raw duration: 3 entries, e.g. {"metric": "duration", "path": "Probe", "method": "GET", "mean": 0.29544221951230765, "count": 41}
aggregate event-loop-delay: 1 rows, keys [(None, None, None, 2)]
   e.g. {"id": [1792586572118.3213, -1347326683], "period": 10000, "metric": "event-loop-delay", "mean": 1.098317913043477, "maxDelay": 2.7082230000000003, "count": 46, "thread": 2, "time": 1792586567105.4475}
aggregate request-time: 2 rows, keys [('Probe', 'POST', None, None), ('Probe', 'PUT', None, None)]
   e.g. {"id": [1792586572117.088, -1347326683], "period": 10000, "metric": "request-time", "path": "Probe", "method": "PUT", "mean": 0.36905937500002894, "count": 40, "median": 0.23127855584025384, "time": 1792586567105.4475}
aggregate duration-by-thread: 1 rows, keys [(None, None, None, 2)]
   e.g. {"id": [1792586572114.9182, -1347326683], "period": 10000, "metric": "duration-by-thread", "count": 91, "mean": 0.3209721538462043, "thread": 2, "time": 1792586567105.4475}
aggregate duration: 3 rows, keys [('Probe', 'GET', None, None), ('Probe', 'POST', None, None), ('Probe', 'PUT', None, None)]
   e.g. {"id": [1792586572113.6365, -1347326683], "period": 10000, "metric": "duration", "path": "Probe", "method": "GET", "mean": 0.29544221951230765, "count": 41, "median": 0.11176719814538956, "time": 1792586567105.4475}
stopped

Benchmark, requests per second

Two workers, one exported table, keep-alive, 50 concurrent loops, 20 s after a 5 s warm-up, only 2xx responses counted, failed: 0 in every run, against the then merge base 3fd9ae9.

build, analytics	GET req/s	GET p50 ms	PUT (queued) req/s	PUT p50 ms
merge base 3fd9ae9, on	30,069 / 31,034	1.40 / 1.40	24,901 / 24,744	1.78 / 1.78
branch, on	31,026 / 31,774	1.25 / 1.25	24,851 / 25,105	1.78 / 1.78
branch, off	31,186	1.20	25,321	1.75

uWS, analytics on: GET 30,359 / 30,302 base against 30,617 / 30,271 branch; queued PUT 25,077 / 26,945 against 25,438 / 24,899. Operations-API POST describe_all through Fastify: 17,214 against 17,320.

Stall past the flush deadline, measured before the fix

With Node 24's monitorEventLoopDelay, a 300 ms stall across the flush deadline was lost in 8 of 20 trials when a timer callback stalled, and 19 of 20 when a check-phase callback did. Arming the flush with a fresh 0 ms timer from the deadline captured it 20 of 20.

Lavinia, via Claude

_{🤖 Generated by Anthropic Claude (Opus 5.5); posted via @ldt1996.}

Release target: main — new analytics metrics and an aggregate row fix for 5.4, not a backport

Related PRs: #3234 overlaps (it would send GET, HEAD and OPTIONS through the request queue, which request-time does not stamp today), #3139 overlaps (merged; its measure-count fold is kept in the byThread fold), 3 others independent

Complexity: complicated

Deferred findings

• 16d18ee0ef8a27d4 minor unclassified — unitTests/server/serverHelpers/requestTimePlugin.test.js — Fastify hook test supplies the stamp; no end-to-end proof http.ts:911 reaches request.raw — NOT FILED
• baacdcc9311f6223 minor unclassified — server/http.ts — uWS request injected into Fastify loses its request-time stamp — NOT FILED
• f1971fdfa7beb6d2 minor unclassified — resources/analytics/write.ts — mandatory per-thread fan-out multiplies audited analytics rows — NOT FILED
• cbf5a2b2d17bf71b minor correctness — resources/analytics/write.ts — window-open histogram reset drops a stall begun in the opening turn; past the deadline the report has no event-loop-delay entry — NOT FILED

_{Review-Coverage: authored=claude; ran=codex,gemini; adjudicated=domain; blocked=claude(fallback)(out-of-budget); declined=cursor-grok,cursor-composer,cursor-kimi,cursor-muse,muse; rounds=17; full=8 @ 5e87ee7}

_{Review-Attention: deep ~50m (critical: write.ts; hot: http.ts; decisions: do-less-alternative, destructive-histogram-reset, always-on-sampler-resolution, request-time-scope, duration-by-thread-no-switch, stamp-as-plain-property, release-target-unclear) @ 5e87ee7}

[dawsontoth]

@laviniat1996 can you cross-model review?

[kriszyp]

Yeah, you can not pass CI without cross-model-review: https://github.com/HarperFast/harper/actions/runs/37805216175/job/113407611478?pr=3110

[dawsontoth]

This will be great to integrate into Studio too! Still waiting on that cross-model review ;D

[dawsontoth]

Are the units for the measurements all milliseconds?

[ldt1996]

@dawsontoth Yes: every time value is milliseconds, and every count is a plain count. event-loop-delay reports mean and maxDelay as lateness past the 20 ms sampling interval, so an idle loop reads about 0, and its count is sampler firings. request-time and duration-by-thread report handler-side milliseconds, with count as requests and responses. The docs companion is HarperFast/documentation#744.

Lavinia, via Claude

_{🤖 Generated by Anthropic Claude (Opus 5.5); posted via @ldt1996.}

[kriszyp]

_{🤖 Reviewed with Codex}

[kriszyp]

Could EventLoopDelay also remain module-private? The constant is now private and the two request-timing interfaces were deleted, addressing three parts of the earlier finding. This interface still has no visible consumer importing its exported name; removing export keeps the named module surface to the helpers callers use.

[kriszyp]

Could the helper-only symbols remain module-private? EVENT_LOOP_DELAY_RESOLUTION_MS and EventLoopDelay are used only within this file, while TimedRequest and TimedSocket are used only within server/serverHelpers/requestTiming.ts:1-7. No import in this checkout consumes those exports. Removing their export keywords keeps the module API to the functions callers actually use.