Anatomy of an HTTP Request — Where the Time Actually Goes

// main.go — print per-phase timings by tracing the HTTP connection
package main

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

func main() {
	url := "https://jsonplaceholder.typicode.com/posts/1"

	var (
		t0                                          = time.Now()
		dnsStart, dnsEnd, connStart, connEnd         time.Time
		tlsStart, tlsEnd, reqWritten, firstByte      time.Time
	)

	trace := &httptrace.ClientTrace{
		DNSStart:             func(_ httptrace.DNSStartInfo) { dnsStart = time.Now() },
		DNSDone:              func(_ httptrace.DNSDoneInfo) { dnsEnd = time.Now() },
		ConnectStart:         func(_, _ string) { connStart = time.Now() },
		ConnectDone:          func(_, _ string, _ error) { connEnd = time.Now() },
		TLSHandshakeStart:    func() { tlsStart = time.Now() },
		TLSHandshakeDone:     func(_ tls.ConnectionState, _ error) { tlsEnd = time.Now() },
		WroteRequest:         func(_ httptrace.WroteRequestInfo) { reqWritten = time.Now() },
		GotFirstResponseByte: func() { firstByte = time.Now() },
	}

	req, _ := http.NewRequest("GET", url, nil)
	req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))

	resp, _ := http.DefaultClient.Do(req)
	io.Copy(io.Discard, resp.Body)
	resp.Body.Close()
	total := time.Since(t0)

	ms := func(a, b time.Time) int64 { return b.Sub(a).Milliseconds() }
	fmt.Printf("DNS lookup:    %3d ms\n", ms(dnsStart, dnsEnd))
	fmt.Printf("TCP connect:   %3d ms\n", ms(connStart, connEnd))
	fmt.Printf("TLS handshake: %3d ms\n", ms(tlsStart, tlsEnd))
	fmt.Printf("Request send:  %3d ms\n", ms(tlsEnd, reqWritten))
	fmt.Printf("Server (TTFB): %3d ms\n", ms(reqWritten, firstByte))
	fmt.Printf("Transfer:      %3d ms\n", ms(firstByte, t0.Add(total)))
	fmt.Printf("Total:         %3d ms\n", total.Milliseconds())
}