[mutianf]

The bug

Pacemaker is meant to report how long its goroutine waits to be scheduled, as a proxy for CPU contention. It computed that as the gap between consecutive tick timestamps, minus the interval:

actualInterval := t.Sub(lastTick)
delay := actualInterval - interval

t is not the delivery time. time.sendTime backdates every tick to the time it was due, and the runtime's own comment says why:

// delta is how long ago the channel send was supposed to happen.
// The current time can be arbitrarily far into the future, because the runtime
// can delay a sendTime call until a goroutine tries to receive from
// the channel. Subtract delta to go back to the old time that we used to send.
case c.(chan Time) <- Now().Add(Duration(-delta)):

Consecutive due times are exactly one interval apart by construction, so actualInterval - interval is zero unless the runtime drops a tick outright. The metric could only see starvation lasting longer than a full 100ms interval, and only in 100ms steps — meaning its eight bucket boundaries below 100ms (100us through 50ms) recorded nothing but timer jitter.

Measured with 32 CPU-bound goroutines on GOMAXPROCS=1, comparing what the code recorded against the goroutine's true wait:

tick   as-written    receive-vs-due
0      0s            16ms
1      0s            17ms
2      439ns         18ms
3      0s            19ms
4      0s            20ms
...
as-written recorded exactly 0 on 15/30 ticks

Up to 20ms of real scheduling delay, reported as 573ns at worst.

The fix

Compare the due time against the time we actually read the tick. Since the channel value is the due time, that difference is the scheduling delay directly — no dependence on dropped ticks, no quantization by the interval. Under the same 32-goroutine workload the metric now reports a mean of 8.7ms.

The computation moves into a recordTick method so the semantics can be tested without timing dependence.

Note for reviewers

This changes what an existing exported metric reports: pacemaker_delays will go from near-zero to real values on any contended client. That is the point of the change, but if anything alerts on this metric today, the thresholds were calibrated against a signal that was always ~0 and will need revisiting.

Testing

• TestPacemakerRecordTick — table test pinning the semantics, including the case the old code could not represent (starvation shorter than one interval, which drops no ticks).
• TestPacemakerRecordTickNeverNegative — a due time in the future records 0, not a negative sample.
• Existing TestPacemakerExporting still passes; full go test -race ./internal/transport/ green.

[gemini-code-assist]

Code Review

This pull request refactors the Pacemaker scheduling delay monitor to measure latency by comparing the actual tick handling time against its scheduled due time, rather than comparing consecutive tick timestamps. This allows the pacemaker to detect starvation shorter than a full interval. Corresponding unit tests were added to verify the accuracy of the recorded delays and ensure negative delays are never recorded. The feedback suggests a minor improvement in recordTick to use Go's idiomatic time.Microsecond constant for duration conversion instead of hardcoded division.

[gemini-code-assist]

Instead of hardcoding 1e3 and calling Nanoseconds(), it is more idiomatic and readable in Go to divide the time.Duration by time.Microsecond to convert it to a fractional microsecond value. This avoids magic numbers and leverages the standard library's duration constants.

Suggested change

	p.histogram.Record(ctx, float64(delay.Nanoseconds())/1e3, p.attrs)
	p.histogram.Record(ctx, float64(delay)/float64(time.Microsecond), p.attrs)

[mutianf]

Applied in ca2fe36. Confirmed numerically identical to the previous form (bit-for-bit across 5M random durations and at the int64 extremes), so this is a pure readability change — and it matches session_tracer.go:315,329 in this same package, which already records durations into histograms as float64(x)/float64(time.Millisecond).