diff --git a/CHANGELOG.md b/CHANGELOG.md index f3fa1ea..895a403 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,15 @@ All completed features are logged here in reverse-chronological order. --- +## 2026-07-01 00:08 — Per-phase breakdown (Go, Step 2) + +- Instrumented requests with `net/http/httptrace.ClientTrace` +- DNS lookup, TCP connect, TLS handshake, Server/TTFB, Transfer, Total phases +- TLS row omitted automatically for plain `http://` URLs +- Aligned text output with separator before Total + +--- + ## 2026-07-01 00:08 — Simple total latency (Go, Step 1) - `probe.Measure` performs an HTTP GET and records wall-clock total time diff --git a/README.md b/README.md index f483c09..6652940 100644 --- a/README.md +++ b/README.md @@ -91,7 +91,7 @@ https://example.com (5 samples) |------|---------|--------| | 0 | Project scaffold — directory structure, `go.mod`, minimal binary | ✅ Done | | 1 | Simple total latency — single URL, wall-clock time | ✅ Done | -| 2 | Per-phase breakdown — DNS, TCP, TLS, TTFB, transfer (`net/http/httptrace`) | ⬜ Pending | +| 2 | Per-phase breakdown — DNS, TCP, TLS, TTFB, transfer (`net/http/httptrace`) | ✅ Done | | 3 | Multiple URLs + `--count`/`-n` — min/avg/max aggregates | ⬜ Pending | | 4 | `--json` output flag | ⬜ Pending | diff --git a/docs/usage/step-2-phase-breakdown.md b/docs/usage/step-2-phase-breakdown.md new file mode 100644 index 0000000..4495767 --- /dev/null +++ b/docs/usage/step-2-phase-breakdown.md @@ -0,0 +1,80 @@ +# Step 2 — Per-Phase Breakdown + +## What this step delivers + +`latprobe` now shows a full breakdown of every phase of an HTTP request: + +| Phase | What it measures | +|-------|-----------------| +| DNS lookup | Time to resolve the hostname (`DNSStart` → `DNSDone`) | +| TCP connect | Time to establish the TCP connection (`ConnectStart` → `ConnectDone`) | +| TLS handshake | Time to complete TLS negotiation — HTTPS only (`TLSHandshakeStart` → `TLSHandshakeDone`) | +| Server (TTFB) | Time from request sent to first response byte (`WroteRequest` → `GotFirstResponseByte`) | +| Transfer | Time to download the response body (`GotFirstResponseByte` → body closed) | +| Total | Wall-clock time for the entire request | + +The TLS row is omitted automatically for plain `http://` URLs. + +Implemented via `net/http/httptrace.ClientTrace` — stdlib only, no external dependencies. + +## Build + +```sh +cd go +go build -o latprobe . +``` + +## Usage + +```sh +latprobe [url ...] +``` + +## Examples + +### HTTPS (all phases present) + +```sh +$ ./latprobe https://example.com +https://example.com (200) + DNS lookup : 18.21 ms + TCP connect : 10.12 ms + TLS handshake : 36.11 ms + Server (TTFB) : 21.95 ms + Transfer : 0.18 ms + ───────────────────────────── + Total : 88.00 ms +``` + +### HTTP (TLS row omitted) + +```sh +$ ./latprobe http://example.com +http://example.com (200) + DNS lookup : 1.64 ms + TCP connect : 9.29 ms + Server (TTFB) : 17.96 ms + Transfer : 0.07 ms + ───────────────────────────── + Total : 29.56 ms +``` + +### Multiple URLs + +```sh +$ ./latprobe https://example.com https://www.google.com +https://example.com (200) + DNS lookup : 18.21 ms + ... + +https://www.google.com (200) + DNS lookup : 7.15 ms + ... +``` + +## Notes + +- **DNS absent on repeat connections**: when the OS has cached the DNS result, + the DNS phase may be very short or absent. This is expected. +- **Phases don't always sum exactly to Total**: the trace hooks introduce + negligible overhead between events; the difference is typically < 1 ms. diff --git a/go/internal/probe/probe.go b/go/internal/probe/probe.go index 395a28d..1982843 100644 --- a/go/internal/probe/probe.go +++ b/go/internal/probe/probe.go @@ -2,8 +2,11 @@ package probe import ( + "context" + "crypto/tls" "io" "net/http" + "net/http/httptrace" "time" ) @@ -30,14 +33,46 @@ type Result struct { Err error } -// Measure performs an HTTP GET to url and returns a Result. -// In Step 1 only the Total phase is populated. +// Measure performs an HTTP GET to url and returns a Result with all phases +// populated via net/http/httptrace. func Measure(url string) Result { r := Result{URL: url} - start := time.Now() + var ( + dnsStart time.Time + dnsDone time.Time + connectStart time.Time + connectDone time.Time + tlsStart time.Time + tlsDone time.Time + wroteRequest time.Time + firstByte time.Time + ) - resp, err := http.Get(url) //nolint:noctx + trace := &httptrace.ClientTrace{ + DNSStart: func(_ httptrace.DNSStartInfo) { dnsStart = time.Now() }, + DNSDone: func(_ httptrace.DNSDoneInfo) { dnsDone = time.Now() }, + ConnectStart: func(_, _ string) { + if connectStart.IsZero() { + connectStart = time.Now() + } + }, + ConnectDone: func(_, _ string, _ error) { connectDone = time.Now() }, + TLSHandshakeStart: func() { tlsStart = time.Now() }, + TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { tlsDone = time.Now() }, + WroteRequest: func(_ httptrace.WroteRequestInfo) { wroteRequest = time.Now() }, + GotFirstResponseByte: func() { firstByte = time.Now() }, + } + + ctx := httptrace.WithClientTrace(context.Background(), trace) + req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil) + if err != nil { + r.Err = err + return r + } + + start := time.Now() + resp, err := http.DefaultClient.Do(req) if err != nil { r.Err = err r.Total = Phase{Duration: time.Since(start), Present: true} @@ -46,11 +81,30 @@ func Measure(url string) Result { defer resp.Body.Close() _, err = io.Copy(io.Discard, resp.Body) + end := time.Now() - r.Total = Phase{Duration: time.Since(start), Present: true} r.StatusCode = resp.StatusCode if err != nil { r.Err = err } + + r.Total = Phase{Duration: end.Sub(start), Present: true} + + if !dnsStart.IsZero() && !dnsDone.IsZero() { + r.DNS = Phase{Duration: dnsDone.Sub(dnsStart), Present: true} + } + if !connectStart.IsZero() && !connectDone.IsZero() { + r.Connect = Phase{Duration: connectDone.Sub(connectStart), Present: true} + } + if !tlsStart.IsZero() && !tlsDone.IsZero() { + r.TLS = Phase{Duration: tlsDone.Sub(tlsStart), Present: true} + } + if !wroteRequest.IsZero() && !firstByte.IsZero() { + r.TTFB = Phase{Duration: firstByte.Sub(wroteRequest), Present: true} + } + if !firstByte.IsZero() { + r.Transfer = Phase{Duration: end.Sub(firstByte), Present: true} + } + return r } diff --git a/go/main.go b/go/main.go index 212ba6d..e4e84ca 100644 --- a/go/main.go +++ b/go/main.go @@ -4,7 +4,7 @@ import ( "flag" "fmt" "os" - "time" + "strings" "latprobe/internal/probe" ) @@ -44,17 +44,48 @@ func main() { _ = count failed := false - for _, url := range urls { + for i, url := range urls { + if i > 0 { + fmt.Println() + } r := probe.Measure(url) if r.Err != nil { - fmt.Fprintf(os.Stderr, "error %s: %v\n", url, r.Err) + fmt.Fprintf(os.Stderr, "error %s: %v\n", r.URL, r.Err) failed = true continue } - fmt.Printf("%-45s %d %v\n", r.URL, r.StatusCode, r.Total.Duration.Round(time.Millisecond)) + printResult(r) } if failed { os.Exit(1) } } + +func printResult(r probe.Result) { + fmt.Printf("%s (%d)\n", r.URL, r.StatusCode) + + phases := []struct { + label string + p probe.Phase + }{ + {"DNS lookup ", r.DNS}, + {"TCP connect ", r.Connect}, + {"TLS handshake ", r.TLS}, + {"Server (TTFB) ", r.TTFB}, + {"Transfer ", r.Transfer}, + } + + for _, ph := range phases { + if ph.p.Present { + fmt.Printf(" %s : %8.2f ms\n", ph.label, msec(ph.p)) + } + } + + fmt.Println(" " + strings.Repeat("─", 29)) + fmt.Printf(" %s : %8.2f ms\n", "Total ", msec(r.Total)) +} + +func msec(p probe.Phase) float64 { + return float64(p.Duration.Microseconds()) / 1000 +}