How do you time the wrapped http.Handler inside a Go middleware function?
answer
- bracket the call, do not replace it
- one clock read before, one after
- defer, so a panic still counts
- the closure, not the argument
- time.Since(start) evaluated at return
basics
~10 sRead start := time.Now() before calling next.ServeHTTP, then record time.Since(start) inside a deferred closure. Deferring means the duration is still recorded when the handler panics or returns early.
solid answer
~40 sGo middleware is `func(next http.Handler) http.Handler`, so it can bracket the call. I take `start := time.Now()` at the top, register `defer func() { record(time.Since(start)) }()`, then call `next.ServeHTTP(w, r)`. The closure matters: `defer record(time.Since(start))` evaluates its argument at the `defer` statement, not when the deferred call runs, so it would record roughly zero every time. Deferring rather than recording on the line after `ServeHTTP` also means a panicking handler still produces a data point — otherwise the slowest and most broken requests are exactly the ones missing from the latency numbers. `time.Since` subtracts monotonic clock readings, so the value survives clock corrections. The span it covers is handler work: it starts when my middleware runs and ends when `ServeHTTP` returns, not when the last byte reaches the client.
code
go · 9 linesfunc 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)
})
}go deeper
Be ready to write the six lines from memory: capture time.Now, defer a closure that records, then call next.ServeHTTP. Know that deferred functions run on the way out, including while a panic unwinds.
Explain when a deferred call's arguments are evaluated and why that turns a one-line timer into a metric that always reports zero. Be able to say exactly which span of the request the number covers.
Show what you do with the duration: which requests must still be counted (panics, early returns, cancelled contexts), and how you capture the status alongside it without breaking streaming handlers underneath.
Own the convention. One timing middleware in a shared internal package rather than a copy per service, and a written definition of the span it measures, so latency numbers from different teams mean the same thing.
## 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.
- Why does defer record(time.Since(start)) report almost zero?Because a deferred call's arguments are evaluated when the `defer` statement executes, not when the call finally runs. `time.Since(start)` is computed immediately after `start` is taken and that frozen `Duration` is what gets passed at return. Putting the call inside `defer func() { ... }()` moves the evaluation to return time.
- The middleware has the duration, but how does it get the status code?`ServeHTTP` returns nothing, so you pass the handler a wrapper around the `http.ResponseWriter` that records the code handed to `WriteHeader`, defaulting to 200 because a handler that only calls `Write` never calls `WriteHeader`. If the handler panics before writing anything the wrapper still holds its zero value, so decide explicitly what you record in that case.
- Does the recorded duration include the response reaching the client?No. It ends when `ServeHTTP` returns, and at that point the handler's writes have only reached the connection's buffered writer; `net/http` finishes the response afterwards. It also excludes the header parsing `net/http` did before your middleware ran. It measures handler work, which is a useful number as long as everyone reads it that way.
saying these in an interview costs you the question
- Recording only after next.ServeHTTP returns, so panicking requests never appear
- Writing defer record(time.Since(start)) and reporting near-zero durations
- Keeping the start time in a package-level variable shared across requests
- Assuming ServeHTTP returns the status code the handler wrote
- Claiming the duration covers bytes arriving at the client