dial9-zoom-window

Zooming into a time window

Aggregate analysis averages over the whole trace; it cannot show what was happening around a single event. Pick a timestamp and reconstruct the instant: which polls ran on which workers, who was on-CPU, whether the queue was backed up.

Pair with dial9-diagnose-long-poll (applies this windowing to root-cause one poll) and dial9-runtime (the execution model).

When to zoom

Zoom after an aggregate pass has given you a timestamp of interest:

• A long poll from red_flag_scan.js (Poll of 53.1ms ... at 6953.5ms) — but note that "long" is relative: judge a poll by how far it sits in this runtime's own poll-duration tail (pollDurationByLoc p99), not an absolute millisecond cutoff. See dial9-diagnose-long-poll for the calibration.
• A scheduling-delay outlier or queue-depth spike
• A pollDurationByLoc max you want to see in context
• A specific request_id whose spans you've located in time

Do not zoom to go fishing in a healthy trace — you'll drown in microsecond polls. Start aggregate, then zoom to the timestamp the aggregate flagged.

The mechanics: timestamps

dial9 timestamps are nanoseconds. Every tool reports time relative to the start of the trace in milliseconds (+6953.5ms). To convert a relative-ms position to an absolute timestamp:

absoluteNs = trace.minTs + relMs * 1e6

A window is [center - half, center + half]. Pick half to be a few times the duration of the event you're studying: for a 53ms poll, a ±40ms half-window shows the poll plus what bracketed it on both sides.

Run it

node scripts/zoom.js <trace.bin|dir> <centerMs> [halfWindowMs=20]

centerMs is the relative-ms timestamp from the aggregate tools.

Example — zoom on a 53ms long poll the red-flag scan reported at +6953ms:

node scripts/zoom.js /tmp/traces/host3/trace.bin.gz 6980 40

What it shows, and how to read each section

1. Cross-worker poll timeline

Every poll overlapping the window, across all workers, ordered by start time. * marks polls > 1ms, annotated with on-CPU / off-CPU. This is the "what ran when" view — read it top to bottom like a tape.

What to look for:

• A single * poll that dwarfs everything else → your event. Note its worker.
• A burst of polls for one task= → a hot connection or a tight wake loop.
• A gap with no polls → the runtime was parked (nothing to do) or everything was blocked inside one long poll.

2. Per-worker busy time

How many ms of the window each worker spent inside polls. One worker at ~100% and the rest near 0% means the work is not parallelized across the window — either one task is hogging a worker, or the box is nearly idle with one straggler.

3. Per-OS-thread CPU census ← the section people forget

CPU samples in the window grouped by OS thread (tid), with an estimate of on-CPU time. This is the most important and least obvious view:

perf samples a thread only while it is ON-CPU. A parked/blocked thread produces zero samples. So this census is a census of who was actually running, regardless of what the tokio scheduler thought.

At the 99 Hz default, one sample ≈ 10ms of on-CPU time for that thread. So:

• 5 samples on one tid over a 50ms window ≈ that tid was on-CPU the whole time.
• gaps~10.0ms (evenly spaced) confirms it was continuously running, not bursty.
• A tid here that is not a tokio worker (e.g. a spawn_blocking pool thread, a metrics flusher, the allocator) is often the hidden actor behind a stall.
• No samples at all in the window → the whole box was idle; any long poll in the window is blocked off-box (network/disk), not on local CPU or a local lock.

Do not reason from the aggregate sample rate ("p50 gap was 70ms so the box was idle") — aggregate gaps are large precisely because few threads are on-CPU. Always reason per tid.

4. Global queue depth

Max/min global injection-queue depth in the window. max=0 while a worker sits in a 53ms poll is the proof that the long poll was not causing head-of-line blocking — nothing was waiting behind it. max>0 means work piled up: the long poll (or a busy runtime) was actually delaying other tasks.

5. Inner spans of the dominant poll

If the app installed the tracing layer (Dial9TracingLayer), the tracing spans that executed inside the longest poll, by name. Tells you what code ran inside a long poll even without reading CPU stacks.

From window back to cause

The zoom is descriptive — it shows the instant. To turn "worker 9 sat in a 53ms off-CPU poll while tid=31 ran EmfCollector::flush the whole time" into a root cause and a fix, hand off to dial9-diagnose-long-poll, which formalizes the per-tid census into a holder-vs-off-box verdict and corroborates it across the trace.