Measure request duration on the injectable clock

[paskal]

TestBenchmarks_Handler fails roughly one run in ten on a loaded machine, on assert.InDelta(t, 50000, res.MaxRespTime, 10000). It reproduces on clean master and has nothing to do with what it appears to test: the handler sleeps 50ms and the assertion requires that to land within 60ms of wall time, which a busy CI box does not guarantee.

The cause is a half-wired clock seam. Handler takes its start time from the injectable nowFn, then closes the measurement with time.Since(st):

st := b.nowFn()
defer func() {
    b.update(time.Since(st))
}()

So the bucketing follows nowFn and can be faked, while the measured duration always comes from the wall clock and cannot. A test can control which second a request lands in but not how long it took.

Both ends read nowFn now. In production nowFn is time.Now, and two values from it carry the monotonic readings that Sub prefers, exactly as time.Since does, so the measurement is unchanged there.

With the seam complete the test drives a fake clock instead of sleeping. The handler advances fake time by 50ms per request, so the response-time assertions become exact equality rather than a 10ms band, and the request rate is deterministic too since bucketing already went through nowFn.

Two side effects worth having: the test no longer sleeps 5 seconds, so the package suite drops from about 11s to 5.5s, and the numbers it asserts are now derived rather than approximated.

Verified with 20 consecutive -race runs of the test and repeated full-suite runs, including under parallel load, with no failures.

Does this change what the middleware measures?

No. In production nowFn is time.Now, so b.nowFn().Sub(st) is time.Now().Sub(st), which is what time.Since is defined as. Measured rather than assumed, on this branch against master:

check	before (time.Since)	after (nowFn().Sub)
10ms handler, error vs nominal, 3 runs	+10.12% / +9.79% / +11.16%	+9.74% / +9.65% / +11.19%
50ms handler, error vs nominal, 3 runs	+1.82% / +3.48% / +2.00%	+1.78% / +2.00% / +1.92%

The difference is run-to-run noise. The residual error is time.Sleep overshoot plus per-request handler overhead, roughly a constant ~1ms in both, which is why it shrinks as a share of a longer request.

Comparing the two expressions directly over 5000 samples, time.Since(st) exceeds nowFn().Sub(st) by a mean of 22-29ns and never less, because Since samples the clock one statement later. Both keep the monotonic reading, so neither is exposed to wall-clock adjustment.

[coveralls]

Coverage Report for CI Build 32197939154

Coverage decreased (-0.04%) to 97.454%

Details

• Coverage decreased (-0.04%) from the base build.
• Patch coverage: 3 of 3 lines across 1 file are fully covered (100%).
• No coverage regressions found.

Uncovered Changes

No uncovered changes found.

Coverage Regressions

No coverage regressions found.

---

Coverage Stats

Relevant Lines:	1571
Covered Lines:	1531
Line Coverage:	97.45%
Coverage Strength:	48.7 hits per line

---

💛 - Coveralls