skip to content

Your Go HTTP client sees 2s per call while the server logs 30ms. How do you find where the time goes?

level: seniorimportance: nice to knowfreq 30%

answer

  1. split the call into phases
  2. the server's clock starts late
  3. hooks ride on the request context
  4. first byte minus request written
  5. the standard library package for client phases

basics

~10 s

Attach a net/http/httptrace ClientTrace to the request context and timestamp its hooks: GetConn, DNSDone, ConnectDone, TLSHandshakeDone, WroteRequest and GotFirstResponseByte. The gaps between them attribute the two seconds to a specific phase.

solid answer

~40 s

Use `net/http/httptrace`. You build a `httptrace.ClientTrace` whose hook functions record timestamps, wrap it into the request's context with `httptrace.WithClientTrace`, and read the deltas: `GetConn` to `GotConn` is time spent obtaining a connection, `DNSStart` to `DNSDone` is resolution, `ConnectStart` to `ConnectDone` is the TCP dial, `TLSHandshakeStart` to `TLSHandshakeDone` is the handshake, and `WroteRequest` to `GotFirstResponseByte` is the server plus the network path. When the server says 30 milliseconds and your first byte is two seconds late, the time is almost never in the handler — it is DNS, a slow dial, the handshake, a proxy in between, or waiting for a connection at all. `GotConnInfo.Reused` and `WasIdle` tell you whether you got a fresh connection every call. Keep the hooks to timestamps: they run on the transport's goroutines and can be called concurrently.

code

go · 21 lines
go
t0 := time.Now()
trace := &httptrace.ClientTrace{
	GetConn: func(hostPort string) {
		log.Printf("want conn %s +%v", hostPort, time.Since(t0))
	},
	GotConn: func(i httptrace.GotConnInfo) {
		log.Printf("got conn reused=%v +%v", i.Reused, time.Since(t0))
	},
	DNSDone: func(httptrace.DNSDoneInfo) {
		log.Printf("dns +%v", time.Since(t0))
	},
	TLSHandshakeDone: func(tls.ConnectionState, error) {
		log.Printf("tls +%v", time.Since(t0))
	},
	GotFirstResponseByte: func() {
		log.Printf("first byte +%v", time.Since(t0))
	},
}

ctx = httptrace.WithClientTrace(ctx, trace)
req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)

go deeper

for a junior

Know that the standard library can time the phases of one outbound call, and that a client-side number always includes connection setup the server never counts.

for a middle

Be able to name the hooks that matter and what each delta measures, especially first byte minus request written, and how the trace is attached through the request context.

for a senior

Turn the deltas into a diagnosis: no connection reuse, queueing for a connection, a resolver problem, or queueing in front of the remote handler — and say what you would change for each.

for a principal

Decide how much of this belongs permanently in the platform: sampled phase timings on every dependency versus a debug flag engineers turn on, and who is expected to reach for it during an incident.

## The gap you are chasing "Client says two seconds, server says thirty milliseconds" is the single most common latency mystery in a service-to-service call, and the honest answer is that the client's number covers work the server never sees. Between your `Do` and the handler's first line sit: obtaining a connection, DNS, TCP connect, the TLS handshake, writing the request, network transit each way, and any proxy or mesh hop. `net/http/httptrace` exists to split that up. ## How it attaches `httptrace` works through the request's context, which means it needs no change to your client or transport: ```go trace := &httptrace.ClientTrace{ /* hooks */ } ctx := httptrace.WithClientTrace(ctx, trace) req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil) ``` The transport looks for a trace on the request's context and calls the hooks you supplied. Because it rides the context, you can enable it for one suspicious call, for a sampled fraction of traffic, or behind a debug flag on a CLI, without touching the shared client. ## The hooks worth timing - `GetConn(hostPort string)` — the transport wants a connection. - `GotConn(GotConnInfo)` — it has one. The struct carries `Reused`, `WasIdle` and `IdleTime`. - `DNSStart` / `DNSDone` — name resolution. - `ConnectStart(network, addr)` / `ConnectDone(network, addr, err)` — the TCP dial, called once per address tried. - `TLSHandshakeStart` / `TLSHandshakeDone(tls.ConnectionState, error)`. - `WroteRequest(WroteRequestInfo)` — the request is fully written. - `GotFirstResponseByte()` — the first byte of the response arrived. Timestamp each against a `t0` taken before `Do` and print the deltas. Twenty lines of code, and it converts "the call is slow" into a phase. ## Reading the result - **`GetConn` to `GotConn` is large, and `Reused` is false.** You are dialling on every call. Either the connection is not being returned for reuse, or the transport is being rebuilt per call, or the per-host limit is making you wait for a free one. - **`GetConn` to `GotConn` is large and no dial happens inside it.** You are queued behind the transport's per-host connection limit — a concurrency problem, not a network one. - **DNS dominates.** A resolver or search-domain problem; the same call by IP will be instant. - **The handshake dominates.** TLS on every call, so again you are not reusing connections; the fix is upstream of the timeout knobs. - **`WroteRequest` to `GotFirstResponseByte` dominates and the server logs 30 ms.** The server's clock starts when its handler runs — queueing in front of it (a proxy, an accept backlog, a saturated listener) or the return path is where your time is. ## Cautions The hook functions are called by the transport on its own goroutines and can run concurrently, including for a request that has already failed. Do timestamps and cheap non-blocking sends, never I/O or lock acquisition that a handler also needs — a blocking hook stalls the request it is measuring. Not every hook is meaningful on every protocol version, so treat a missing `ConnectDone` on a reused connection as expected rather than as a bug. And `httptrace` is a diagnostic, not an SLA: it is per request and its output goes to your log or an in-memory histogram, so leaving it on for every call in a hot path costs you allocations for no benefit. ## Where it sits among the other tools `httptrace` answers *which phase*. It does not answer *why that phase is slow* — for that you go to the network, the resolver, or the dependency. But it is the difference between an argument ("our client is slow" / "our server is fast") and a fact, and on a CLI that fans out to several internal APIs it is often the fastest way to discover that one dependency's name resolves through a stale search path and costs a full second before a single byte moves.

  • The gap between GetConn and GotConn is large. What does that point at?
    Time spent obtaining a connection rather than using one. Either there was no idle connection and you paid for a fresh dial and handshake, or you were queued behind the transport's per-host connection limit. `GotConnInfo.Reused` and `WasIdle` separate the two cases immediately.
  • How do you enable this for one call without changing the shared client?
    Wrap the trace into that request's context with `httptrace.WithClientTrace` and build the request from it. The transport picks the trace off the context, so a debug flag or a sampled fraction of calls can turn it on with no client, transport or call-site restructuring.
  • Any caution about what you put inside the hook functions?
    They run on the transport's goroutines and may be called concurrently, sometimes after the request has failed. Keep them to timestamps and non-blocking sends — doing I/O or taking a contended lock inside a hook slows the very request you are measuring and can deadlock against your own code.

saying these in an interview costs you the question

  • Blames the network without measuring any phase
  • Assumes the server's handler timing covers the client's wait
  • Does logging or I/O inside the trace hooks
  • Thinks httptrace needs a custom transport to work
  • Leaves per-request tracing enabled on every hot-path call