From fa0fa8bdf4c7049e47f5beb4da1a56057bde39fc Mon Sep 17 00:00:00 2001 From: AzarAI <109265168+AzarAI-TOP@users.noreply.github.com> Date: Mon, 15 Jun 2026 11:48:29 +0800 Subject: [PATCH] feat(timing): add --timing request phase breakdown (#14) Add a --timing flag that prints how long each phase of a request took: DNS lookup, TCP connection, TLS handshake, server processing (TTFB), content transfer, and total. The phases the Go transport can observe (connect, TLS, request-written, first-response-byte) are collected with net/http/httptrace. DNS is timed separately around the client's own concurrent resolver, since that resolution happens in a custom DialContext that httptrace cannot see. The client returns before the body is read, so it measures up to the first response byte and exposes TimeToFirstByte; main owns the overall wall clock and derives the content-transfer phase (Total - TimeToFirstByte). --timing is also persisted by save/run. Tests cover the phase() helper, that Fetch populates timing against a local server (and leaves it nil when not requested), the --timing flag parsing, and the rendered output format. Co-Authored-By: Claude Opus 4.8 --- client/client.go | 27 ++++++++++- client/timing.go | 108 +++++++++++++++++++++++++++++++++++++++++ client/timing_test.go | 85 ++++++++++++++++++++++++++++++++ main.go | 22 +++++++++ main_test.go | 18 +++++++ printer/printer.go | 29 +++++++++++ printer/timing_test.go | 40 +++++++++++++++ 7 files changed, 328 insertions(+), 1 deletion(-) create mode 100644 client/timing.go create mode 100644 client/timing_test.go create mode 100644 printer/timing_test.go diff --git a/client/client.go b/client/client.go index 624ea11..ac0621c 100644 --- a/client/client.go +++ b/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) } diff --git a/client/timing.go b/client/timing.go new file mode 100644 index 0000000..f12796a --- /dev/null +++ b/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) +} diff --git a/client/timing_test.go b/client/timing_test.go new file mode 100644 index 0000000..1142413 --- /dev/null +++ b/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) + } +} diff --git a/main.go b/main.go index eeef62c..b3afd9d 100644 --- a/main.go +++ b/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") } diff --git a/main_test.go b/main_test.go index a7d3557..e06852b 100644 --- a/main_test.go +++ b/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"}) diff --git a/printer/printer.go b/printer/printer.go index bacd0c6..30e898f 100644 --- a/printer/printer.go +++ b/printer/printer.go @@ -236,6 +236,35 @@ func isHTML(contentType string) bool { return strings.Contains(contentType, "text/html") || strings.Contains(contentType, "application/xhtml+xml") } +// RenderTiming prints the per-phase request timing breakdown. The client +// measures everything up to the first response byte; contentTransfer and total +// are supplied by the caller, which owns the wall-clock window around the body +// read. +func RenderTiming(w io.Writer, t *client.Timing, contentTransfer, total time.Duration, enabled bool) error { + if _, err := fmt.Fprintln(w, sectionTitle(enabled, "TIMING")); err != nil { + return err + } + rows := []struct { + label string + value time.Duration + }{ + {"DNS Lookup", t.DNSLookup}, + {"TCP Connection", t.TCPConnection}, + {"TLS Handshake", t.TLSHandshake}, + {"Server Processing", t.ServerProcessing}, + {"Content Transfer", contentTransfer}, + } + for _, row := range rows { + if _, err := fmt.Fprintf(w, " %-18s %s\n", color.Header(enabled, row.label), row.value.Round(time.Millisecond)); err != nil { + return err + } + } + if _, err := fmt.Fprintf(w, " %-18s %s\n", color.Title(enabled, "Total"), total.Round(time.Millisecond)); err != nil { + return err + } + return nil +} + func sectionTitle(enabled bool, title string) string { return color.Title(enabled, "── "+title+" ──────────────────────────────────────") } diff --git a/printer/timing_test.go b/printer/timing_test.go new file mode 100644 index 0000000..52a0667 --- /dev/null +++ b/printer/timing_test.go @@ -0,0 +1,40 @@ +package printer + +import ( + "bytes" + "strings" + "testing" + "time" + + "brew-terminal-curl/client" +) + +func TestRenderTiming(t *testing.T) { + tm := &client.Timing{ + DNSLookup: 45 * time.Millisecond, + TCPConnection: 30 * time.Millisecond, + TLSHandshake: 120 * time.Millisecond, + ServerProcessing: 200 * time.Millisecond, + TimeToFirstByte: 395 * time.Millisecond, + } + + var buf bytes.Buffer + if err := RenderTiming(&buf, tm, 15*time.Millisecond, 410*time.Millisecond, false); err != nil { + t.Fatalf("RenderTiming returned error: %v", err) + } + out := buf.String() + + for _, want := range []string{ + "TIMING", + "DNS Lookup", "45ms", + "TCP Connection", "30ms", + "TLS Handshake", "120ms", + "Server Processing", "200ms", + "Content Transfer", "15ms", + "Total", "410ms", + } { + if !strings.Contains(out, want) { + t.Errorf("RenderTiming output missing %q\n--- output ---\n%s", want, out) + } + } +}