feat(timing): add --timing request phase breakdown (#14)

client/client.go

@@ -8,6 +8,7 @@ import (
 	"io"
 	"net"
 	"net/http"
+	"net/http/httptrace"
 	"net/url"
 	"strings"
 	"time"
@@ -20,6 +21,7 @@ type Options struct {
 	Headers []string
 	Timeout time.Duration
 	Verbose bool
+	Timing  bool
 }
 
 type RedirectHop struct {
@@ -33,6 +35,9 @@ type Result struct {
 	Request   *http.Request
 	Response  *http.Response
 	Redirects []RedirectHop
+	// Timing is populated only when Options.Timing is set. ContentTransfer and
+	// the overall total are filled in by the caller once the body is consumed.
+	Timing *Timing
 }
 
 func Fetch(opts Options) (*Result, error) {
@@ -153,6 +158,13 @@ func fetchSingleWithContext(ctx context.Context, opts Options, target string) (*
 	body := opts.Data
 	var redirects []RedirectHop
 
+	var timing *timingCollector
+	if opts.Timing {
+		timing = newTimingCollector()
+		ctx = withTiming(ctx, timing)
+		ctx = httptrace.WithClientTrace(ctx, timing.clientTrace())
+	}
+
 	for attempt := 0; attempt < 10; attempt++ {
 		req, err := http.NewRequestWithContext(ctx, method, requestURL, bytes.NewReader(body))
 		if err != nil {
@@ -189,7 +201,11 @@ func fetchSingleWithContext(ctx context.Context, opts Options, target string) (*
 			continue
 		}
 
-		return &Result{Request: req, Response: resp, Redirects: redirects}, nil
+		result := &Result{Request: req, Response: resp, Redirects: redirects}
+		if timing != nil {
+			result.Timing = timing.result()
+		}
+		return result, nil
 	}
 
 	return nil, fmt.Errorf("too many redirects")
@@ -266,7 +282,16 @@ func tunedTransport() *http.Transport {
 				return nil, err
 			}
 
+			// DNS happens in our own concurrent resolver, which httptrace
+			// cannot see, so time it here for the --timing breakdown.
+			tc := timingFrom(ctx)
+			if tc != nil {
+				tc.markDNSStart()
+			}
 			ips, err := resolveHostConcurrent(ctx, host)
+			if tc != nil {
+				tc.markDNSDone()
+			}
 			if err != nil {
 				return dialer.DialContext(ctx, network, addr)
 			}

client/timing.go

@@ -0,0 +1,108 @@
+package client
+
+import (
+	"context"
+	"crypto/tls"
+	"net/http/httptrace"
+	"sync"
+	"time"
+)
+
+// Timing captures how long each phase of an HTTP request took. It is populated
+// only when Options.Timing is set.
+//
+// ContentTransfer and Total are intentionally left out here: the client returns
+// as soon as the response headers are available, before the body has been read,
+// so those two phases can only be known by the caller once it has finished
+// consuming the body. The caller derives them from TimeToFirstByte:
+//
+//	Total           = total elapsed once the body is fully read
+//	ContentTransfer = Total - TimeToFirstByte
+type Timing struct {
+	DNSLookup        time.Duration // resolving the hostname
+	TCPConnection    time.Duration // establishing the TCP connection
+	TLSHandshake     time.Duration // TLS negotiation (zero for plain http or a reused connection)
+	ServerProcessing time.Duration // request written -> first response byte
+	TimeToFirstByte  time.Duration // request start -> first response byte
+}
+
+// timingKey is the context key under which a timingCollector is carried, so the
+// custom DialContext can record the DNS phase that httptrace cannot observe for
+// this client (resolution happens in our own concurrent resolver, not the Go
+// transport's default resolver).
+type timingKey struct{}
+
+func withTiming(ctx context.Context, tc *timingCollector) context.Context {
+	return context.WithValue(ctx, timingKey{}, tc)
+}
+
+func timingFrom(ctx context.Context) *timingCollector {
+	tc, _ := ctx.Value(timingKey{}).(*timingCollector)
+	return tc
+}
+
+// timingCollector records timestamps for each request phase. All marks use
+// "latest wins" semantics so that, across a redirect chain, the durations
+// reflect the connection that actually served each phase (a reused keep-alive
+// connection simply never re-fires ConnectStart/TLSHandshakeStart, leaving the
+// original establishment timings in place).
+type timingCollector struct {
+	mu           sync.Mutex
+	start        time.Time
+	dnsStart     time.Time
+	dnsDone      time.Time
+	connectStart time.Time
+	connectDone  time.Time
+	tlsStart     time.Time
+	tlsDone      time.Time
+	wroteRequest time.Time
+	firstByte    time.Time
+}
+
+func newTimingCollector() *timingCollector {
+	return &timingCollector{start: time.Now()}
+}
+
+func (tc *timingCollector) mark(field *time.Time) {
+	tc.mu.Lock()
+	*field = time.Now()
+	tc.mu.Unlock()
+}
+
+// clientTrace wires the phases the Go transport can observe directly: the TCP
+// connect, the TLS handshake, the moment the request was written, and the first
+// response byte. DNS is handled separately in DialContext (see markDNS*).
+func (tc *timingCollector) clientTrace() *httptrace.ClientTrace {
+	return &httptrace.ClientTrace{
+		ConnectStart:         func(_, _ string) { tc.mark(&tc.connectStart) },
+		ConnectDone:          func(_, _ string, _ error) { tc.mark(&tc.connectDone) },
+		TLSHandshakeStart:    func() { tc.mark(&tc.tlsStart) },
+		TLSHandshakeDone:     func(tls.ConnectionState, error) { tc.mark(&tc.tlsDone) },
+		WroteRequest:         func(httptrace.WroteRequestInfo) { tc.mark(&tc.wroteRequest) },
+		GotFirstResponseByte: func() { tc.mark(&tc.firstByte) },
+	}
+}
+
+func (tc *timingCollector) markDNSStart() { tc.mark(&tc.dnsStart) }
+func (tc *timingCollector) markDNSDone()  { tc.mark(&tc.dnsDone) }
+
+func (tc *timingCollector) result() *Timing {
+	tc.mu.Lock()
+	defer tc.mu.Unlock()
+	return &Timing{
+		DNSLookup:        phase(tc.dnsStart, tc.dnsDone),
+		TCPConnection:    phase(tc.connectStart, tc.connectDone),
+		TLSHandshake:     phase(tc.tlsStart, tc.tlsDone),
+		ServerProcessing: phase(tc.wroteRequest, tc.firstByte),
+		TimeToFirstByte:  phase(tc.start, tc.firstByte),
+	}
+}
+
+// phase returns b-a, or zero if either endpoint was never recorded or the
+// timestamps are out of order (e.g. a reused connection that skipped a phase).
+func phase(a, b time.Time) time.Duration {
+	if a.IsZero() || b.IsZero() || b.Before(a) {
+		return 0
+	}
+	return b.Sub(a)
+}

client/timing_test.go

@@ -0,0 +1,85 @@
+package client
+
+import (
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+	"time"
+)
+
+func TestPhase(t *testing.T) {
+	base := time.Now()
+	later := base.Add(20 * time.Millisecond)
+
+	if got := phase(base, later); got != 20*time.Millisecond {
+		t.Errorf("phase(base, base+20ms) = %v, want 20ms", got)
+	}
+	if got := phase(time.Time{}, later); got != 0 {
+		t.Errorf("phase with zero start = %v, want 0", got)
+	}
+	if got := phase(base, time.Time{}); got != 0 {
+		t.Errorf("phase with zero end = %v, want 0", got)
+	}
+	if got := phase(later, base); got != 0 {
+		t.Errorf("phase with end before start = %v, want 0", got)
+	}
+}
+
+func TestFetchPopulatesTiming(t *testing.T) {
+	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		// A small delay so server-processing and TTFB are clearly measurable.
+		time.Sleep(10 * time.Millisecond)
+		w.WriteHeader(http.StatusOK)
+		io.WriteString(w, "ok")
+	}))
+	defer server.Close()
+
+	result, err := Fetch(Options{Method: "GET", URL: server.URL, Timeout: 5 * time.Second, Timing: true})
+	if err != nil {
+		t.Fatalf("Fetch returned error: %v", err)
+	}
+	defer result.Response.Body.Close()
+	io.Copy(io.Discard, result.Response.Body)
+
+	if result.Timing == nil {
+		t.Fatal("expected Timing to be populated when Options.Timing is set")
+	}
+	tm := result.Timing
+
+	if tm.TCPConnection <= 0 {
+		t.Errorf("expected a positive TCP connection time, got %v", tm.TCPConnection)
+	}
+	if tm.TimeToFirstByte <= 0 {
+		t.Errorf("expected a positive time-to-first-byte, got %v", tm.TimeToFirstByte)
+	}
+	if tm.ServerProcessing < 0 {
+		t.Errorf("server processing should never be negative, got %v", tm.ServerProcessing)
+	}
+	// Plain HTTP: no TLS handshake should be recorded.
+	if tm.TLSHandshake != 0 {
+		t.Errorf("expected zero TLS handshake for http, got %v", tm.TLSHandshake)
+	}
+	// TTFB is the outermost phase measured by the client; it must bound the
+	// inner phases it contains.
+	if tm.ServerProcessing > tm.TimeToFirstByte {
+		t.Errorf("server processing %v exceeds time-to-first-byte %v", tm.ServerProcessing, tm.TimeToFirstByte)
+	}
+}
+
+func TestFetchWithoutTimingLeavesNil(t *testing.T) {
+	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		io.WriteString(w, "ok")
+	}))
+	defer server.Close()
+
+	result, err := Fetch(Options{Method: "GET", URL: server.URL, Timeout: 5 * time.Second})
+	if err != nil {
+		t.Fatalf("Fetch returned error: %v", err)
+	}
+	defer result.Response.Body.Close()
+
+	if result.Timing != nil {
+		t.Errorf("expected Timing to stay nil when Options.Timing is unset, got %+v", result.Timing)
+	}
+}

main.go

@@ -31,6 +31,7 @@ type cliOptions struct {
 	bodyOnly     bool
 	raw          bool
 	verbose      bool
+	timing       bool
 	outputPath   string
 	showHelp     bool
 	showVersion  bool
@@ -49,6 +50,7 @@ type savedRequest struct {
 	BodyOnly    bool     `json:"body_only,omitempty"`
 	Raw         bool     `json:"raw,omitempty"`
 	Verbose     bool     `json:"verbose,omitempty"`
+	Timing      bool     `json:"timing,omitempty"`
 	OutputPath  string   `json:"output_path,omitempty"`
 	Env         string   `json:"env,omitempty"`
 }
@@ -105,6 +107,7 @@ func runRequest(opts cliOptions) {
 		Headers: opts.headers,
 		Timeout: opts.timeout,
 		Verbose: opts.verbose,
+		Timing:  opts.timing,
 	})
 	if err != nil {
 		fatal(err)
@@ -124,6 +127,20 @@ func runRequest(opts cliOptions) {
 		bw.Flush()
 		fatal(err)
 	}
+
+	// The body is read during Render, so the total wall clock and the
+	// content-transfer phase are only known now.
+	if opts.timing && result.Timing != nil && !opts.raw {
+		total := time.Since(start)
+		contentTransfer := total - result.Timing.TimeToFirstByte
+		if contentTransfer < 0 {
+			contentTransfer = 0
+		}
+		if err := printer.RenderTiming(bw, result.Timing, contentTransfer, total, useColor); err != nil {
+			bw.Flush()
+			fatal(err)
+		}
+	}
 	bw.Flush()
 }
 
@@ -213,6 +230,7 @@ func saveRequestLocally(name string, opts cliOptions) error {
 		BodyOnly:    opts.bodyOnly,
 		Raw:         opts.raw,
 		Verbose:     opts.verbose,
+		Timing:      opts.timing,
 		OutputPath:  opts.outputPath,
 		Env:         opts.env,
 	}
@@ -275,6 +293,7 @@ func loadRequestLocally(name string) (cliOptions, error) {
 	options.bodyOnly = req.BodyOnly
 	options.raw = req.Raw
 	options.verbose = req.Verbose
+	options.timing = req.Timing
 	options.outputPath = req.OutputPath
 	options.env = req.Env
 
@@ -383,6 +402,8 @@ func parseCLIWithBase(base cliOptions, args []string) (cliOptions, error) {
 			options.raw = true
 		case arg == "-v" || arg == "--verbose":
 			options.verbose = true
+		case arg == "--timing":
+			options.timing = true
 		case arg == "-o" || arg == "--output":
 			value, next, err := takeValue(args, i)
 			if err != nil {
@@ -501,6 +522,7 @@ func printUsage() {
 	fmt.Fprintln(os.Stdout, "  --body-only       Show only response body")
 	fmt.Fprintln(os.Stdout, "  --raw             Raw output, no formatting")
 	fmt.Fprintln(os.Stdout, "  -v, --verbose     Show request info too")
+	fmt.Fprintln(os.Stdout, "  --timing          Show per-phase timing (DNS, TCP, TLS, TTFB, transfer)")
 	fmt.Fprintln(os.Stdout, "  -o, --output      Save body to file")
 	fmt.Fprintln(os.Stdout, "  --install-alias   Install zsh/bash alias to prevent url globbing")
 }

main_test.go

@@ -71,6 +71,24 @@ func TestParseCLITimeoutInvalid(t *testing.T) {
 	}
 }
 
+func TestParseCLITimingFlag(t *testing.T) {
+	opts, err := parseCLI([]string{"--timing", "https://example.com"})
+	if err != nil {
+		t.Fatalf("parseCLI returned error: %v", err)
+	}
+	if !opts.timing {
+		t.Fatal("expected --timing to set the timing option")
+	}
+
+	opts, err = parseCLI([]string{"https://example.com"})
+	if err != nil {
+		t.Fatalf("parseCLI returned error: %v", err)
+	}
+	if opts.timing {
+		t.Fatal("expected timing to default to false without --timing")
+	}
+}
+
 // Without an explicit --timeout, the default must remain 30s.
 func TestParseCLITimeoutDefault(t *testing.T) {
 	opts, err := parseCLI([]string{"https://example.com"})