History

Add temporary clock-sync probe to separate pre-work time from real work (#1670)

workerd freezes Date.now() until I/O completes, so any delta taken across a request's first I/O silently includes queueing, isolate start and module evaluation. That artifact made every phase before the first await read 0ms and whichever await came first read multi-second, regardless of what it actually did. Await scheduler.wait(0) at handler entry to force the clock forward, and log the delta it absorbs. That delta is the pre-work time; everything measured after it is honest. Temporary, to be reverted.

Rhys Sullivan committed 2 months ago

Commit 58ebd701 parent c0d25e41 file · +26 −0Browse files

Unified · Split

apps/cloud/src/server.ts+26−0
@@ -179,6 +179,32 @@ const mcpAgentHandler = makeCloudMcpAgentHandler({ · 178 unmodified lines
179179
180180 const cloudflareHandler: ExportedHandler<Env> = {
181181 fetch: async (request, env, ctx) => {
182+ // TEMPORARY DIAGNOSTIC (Aug 2026 latency hunt).
183+ //
184+ // workerd freezes `Date.now()` and only advances it when I/O completes, so
185+ // every `Date.now()` delta taken ACROSS the first I/O of a request silently
186+ // includes all wall-clock since the request started — queueing, isolate
187+ // start, module evaluation. That is why per-phase timings kept reporting
188+ // 0ms for everything up to the first await and then a multi-second number
189+ // for whichever await happened to be first: the instrument was measuring
190+ // the clock jump, not the operation.
191+ //
192+ // `scheduler.wait(0)` is an I/O boundary, so awaiting it here forces the
193+ // clock forward before any real work. The delta it absorbs IS the
194+ // pre-work time (queue + start + module eval); every measurement after it
195+ // is honest.
196+ const entryPinned = Date.now();
197+ await scheduler.wait(0);
198+ const preWorkMs = Date.now() - entryPinned;
199+ const probeUrl = new URL(request.url);
200+ console.log(
201+ JSON.stringify({
202+ probe: "clock-sync",
203+ path: probeUrl.pathname,
204+ preWorkMs,
205+ }),
206+ );
207+
182208 // Public pages must not enter TanStack Start: its first-request dynamic
183209 // import loads the entire React + Effect server graph and can take seconds
184210 // on a cold isolate. Classify and service-bind marketing at the Worker