Blog / Go

991 words

  • go
  • net-http
  • httptrace
  • tls
  • dns
  • observability

Go's httptrace: Timing DNS, Connect and TLS Per Request

A client call takes 1.4 seconds and all you have is the total. http.Client.Timeout will tell you when it gave up, and a stopwatch around client.Do will tell you how long it took, but neither says whether the time went on DNS, on the TCP connect, on the TLS handshake or on the server thinking about your request. Those have four different fixes, so guessing is expensive.

The standard library has had the answer since Go 1.7: net/http/httptrace. You hang callbacks on a context.Context, hand that context to a request, and the transport calls you at each stage. No wrapping of dialers, no packet capture.

The smallest useful version

The hooks I actually use are these: DNSStart/DNSDone, ConnectStart/ConnectDone, TLSHandshakeStart/TLSHandshakeDone, GotConn, WroteRequest and GotFirstResponseByte. There are more (GetConn, WroteHeaders, Got1xxResponse, PutIdleConn and friends) but these nine cover the timeline of one request.

Here is a small recorder. It is complete apart from a main to call it; I ran it against an httptest TLS server on Go 1.22.

package main

import (
	"crypto/tls"
	"fmt"
	"log"
	"net/http"
	"net/http/httptrace"
	"sync"
	"time"
)

// timings records when each phase of one request started and finished.
// Hooks can fire from the dialling goroutine, so it needs a lock.
type timings struct {
	mu                      sync.Mutex
	dnsStart, dnsDone       time.Time
	connStart, connDone     time.Time
	tlsStart, tlsDone       time.Time
	wroteRequest, firstByte time.Time
	reused                  bool
}

// set stores now in *p, but only the first time.
func (t *timings) set(p *time.Time) {
	t.mu.Lock()
	defer t.mu.Unlock()
	if p.IsZero() {
		*p = time.Now()
	}
}

func trace(t *timings) *httptrace.ClientTrace {
	return &httptrace.ClientTrace{
		DNSStart:     func(httptrace.DNSStartInfo) { t.set(&t.dnsStart) },
		DNSDone:      func(httptrace.DNSDoneInfo) { t.set(&t.dnsDone) },
		ConnectStart: func(_, _ string) { t.set(&t.connStart) },
		ConnectDone: func(_, _ string, err error) {
			if err == nil {
				t.set(&t.connDone)
			}
		},
		TLSHandshakeStart: func() { t.set(&t.tlsStart) },
		TLSHandshakeDone:  func(tls.ConnectionState, error) { t.set(&t.tlsDone) },
		GotConn: func(i httptrace.GotConnInfo) {
			t.mu.Lock()
			t.reused = i.Reused
			t.mu.Unlock()
		},
		WroteRequest:         func(httptrace.WroteRequestInfo) { t.set(&t.wroteRequest) },
		GotFirstResponseByte: func() { t.set(&t.firstByte) },
	}
}

func span(a, b time.Time) string {
	if a.IsZero() || b.IsZero() {
		return "-"
	}
	return b.Sub(a).Round(time.Microsecond).String()
}

func (t *timings) String() string {
	t.mu.Lock()
	defer t.mu.Unlock()
	return fmt.Sprintf("reused=%v dns=%s connect=%s tls=%s ttfb=%s",
		t.reused,
		span(t.dnsStart, t.dnsDone),
		span(t.connStart, t.connDone),
		span(t.tlsStart, t.tlsDone),
		span(t.wroteRequest, t.firstByte))
}

The lock is not decoration. The ClientTrace documentation says hooks may be called concurrently from different goroutines, and that some may fire after the request has completed or failed. The dial happens on its own goroutine, so a race detector run without the mutex will complain quickly.

Note what "ttfb" means here: I measure from WroteRequest to GotFirstResponseByte. That is the server's think time plus one network round trip, which is the number you want when separating "the server is slow" from "getting to the server is slow". Measuring from the start of the call would fold the dial into it.

Instrumenting every call with a RoundTripper

Building the context by hand at each call site gets old. A RoundTripper wrapper does it once for the whole client:

type tracingTransport struct{ next http.RoundTripper }

func (tt tracingTransport) RoundTrip(req *http.Request) (*http.Response, error) {
	t := &timings{}
	ctx := httptrace.WithClientTrace(req.Context(), trace(t))
	resp, err := tt.next.RoundTrip(req.WithContext(ctx))
	log.Printf("%s %s: %s", req.Method, req.URL.Host, t)
	return resp, err
}

Use it as &http.Client{Transport: tracingTransport{http.DefaultTransport}}. req.WithContext makes a shallow copy, which is what a RoundTripper is allowed to do; mutating the caller's request is not. And WithClientTrace composes: if the incoming context already carries a trace, both sets of hooks run, yours first. That matters if something else in the stack (an OpenTelemetry HTTP client, say) has already attached one.

Against my test server the output is:

GET localhost:41275: reused=false dns=358µs connect=97µs tls=2.078ms ttfb=219µs
GET localhost:41275: reused=true dns=- connect=- tls=- ttfb=111µs

That second line is the point of the exercise. On a warm keep-alive connection there is no DNS, no connect and no handshake, and the hooks for them do not fire at all. A latency histogram that mixes the two kinds of request will have two humps, and the trace tells you which hump each sample belongs to. It also explains why "the first request after a quiet period is slow" is so common: the idle connection was closed, so you paid for all three again.

Where the numbers lie to you

The hooks are honest, but they describe what the transport did, which is not always what you assumed.

  • Multiple connects. With several addresses for a name, the dialer races them and ConnectStart can fire more than once. That is why my code keeps the first start and the first successful done. Otherwise a slow failed IPv6 attempt finishing late would stretch your "connect" figure.
  • Redirects. The client carries the request context across hops, so a trace attached at the call site fires again for each redirect, and my first-write-wins set would silently keep only the first hop. The RoundTripper version avoids this, because Client calls RoundTrip once per hop and each gets a fresh timings.
  • Proxies. Connect and DNS are for the proxy, not the origin. For HTTPS through an HTTP proxy the TLS handshake starts only after the proxy has answered the CONNECT.
  • Custom dialers. The DNS and connect hooks are wired through net.Dialer and the resolver. If your DialContext does something else entirely, they stay silent. An IP literal in the URL skips DNS, too, so dns=- does not always mean a reused connection; check reused alongside it.
  • Dials that outlive their request. Actually, this bit is interesting. When the pool has no idle connection the transport starts a dial, but if another request finishes and frees a connection first, your request takes that one and the dial carries on to fill the pool. So you can occasionally see dial hooks fire on a request whose GotConn says Reused: true. The dial is real, it just is not the one you waited for.

A timeout that tells you which phase hung

My span helper prints - when a phase has no end time. On a success that means the phase never happened. On a failure it means something more useful: if connStart is set and connDone is not, the request died inside the TCP connect. Same for DNS and TLS. A timeout error alone says "context deadline exceeded" and nothing else, so logging the trace on the error path turns a vague failure into "the handshake hung". You could make span print started instead of - in that case if the ambiguity bothers you; I left it plain.

The TLS callback carries more than a timestamp

TLSHandshakeDone receives the tls.ConnectionState, and I threw it away above. It contains the negotiated version, the cipher suite, the ALPN protocol (so you can see whether you got h2 or http/1.1) and DidResume, which says whether the handshake used a session ticket. If handshakes are the slow part, DidResume is the first thing to check, since a resumed handshake skips the certificate exchange and is meaningfully cheaper. Logging it next to the duration costs one extra field.

One last practical note: hooks run inline on the transport's path, so anything slow in them slows the request. Record a timestamp, take the lock, get out. Do the formatting and logging afterwards, as the wrapper does, and the tracing overhead is a handful of time.Now calls per request.

← Back to the blog