Timing Requests and Calls

## What the middleware has to work with A Go HTTP middleware is a function that takes a handler and returns a handler: ```go func(next http.Handler) http.Handler ``` The returned handler can run code before and after `next.ServeHTTP(w, r)`. That call is the only hook you get, and it is deliberately bare: `ServeHTTP` returns nothing at all — no duration, no status code, no error. Anything you want to report about the request you must capture yourself around that one call. ## The shape of a request timer ```go func timing(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() defer func() { record(r.Method, time.Since(start)) }() next.ServeHTTP(w, r) }) } ``` `record` is your own sink — a histogram, a counter, a log line. Three things in those lines are worth being able to defend. ## Why the closure, not `defer record(time.Since(start))` In Go, the arguments of a deferred call are evaluated **when the `defer` statement executes**, not when the deferred call finally runs. `defer record(time.Since(start))` therefore computes `time.Since(start)` immediately — microseconds after `start` was taken — and schedules `record` with that frozen value. The metric compiles, runs, reports numbers, and every one of them is near zero. Wrapping the work in `func() { ... }()` moves the evaluation inside the function body, which runs at return time. ## Why defer at all You could write `next.ServeHTTP(w, r)` and then the recording line, and for the happy path it behaves identically. It diverges on the paths you most want to see. If the handler panics, the following statement never executes, but deferred functions still run as the goroutine unwinds — so the deferred version records the request and the un-deferred version silently drops it. `net/http` recovers a handler panic per connection so the process survives, which means the failure shows up in your metrics as *nothing at all*: a latency histogram that quietly omits the failing route. The same argument covers any early `return` a future edit adds inside the wrapped code. ## What the measured span actually is The timer starts when your middleware body runs. By then `net/http` has already accepted the connection, read and parsed the request line and headers, and run every middleware outside yours. It stops when `ServeHTTP` returns, at which point the handler's writes have gone into the connection's buffered writer; `net/http` flushes the remainder and finishes the response after the handler returns. So the number is *handler work*, not *time on the wire*, and it excludes both inbound header parsing and the final flush. That is a perfectly good definition — it just has to be the same definition everywhere, or latency numbers from two services are not comparable. ## Why `time.Since` rather than arithmetic on wall-clock fields `time.Now()` returns a `time.Time` that carries a monotonic clock reading alongside the wall clock. `time.Since(start)` is `time.Now().Sub(start)`, and `Sub` uses the monotonic readings when both values have them, so an NTP correction or a manual clock change during the request cannot produce a negative or wildly inflated duration. Formatting the two times and subtracting seconds throws that away. ## Getting the status code alongside the duration A duration on its own cannot separate a fast 500 from a fast 200. Because `ServeHTTP` returns nothing, the usual approach is to pass the handler a wrapper around the `http.ResponseWriter` that remembers the code given to `WriteHeader`, defaulting to 200 for a handler that only calls `Write`. That wrapper has consequences of its own for streaming handlers, and those are worth understanding before you ship one.