feat(go): step 2 — per-phase request breakdown via httptrace
Instruments HTTP requests with net/http/httptrace.ClientTrace to capture timestamps for DNS, TCP connect, TLS handshake, TTFB, and body transfer. TLS row is omitted automatically for plain http:// URLs. Output is an aligned text table with a separator before the Total row. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
This commit is contained in:
@@ -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)
|
## 2026-07-01 00:08 — Simple total latency (Go, Step 1)
|
||||||
|
|
||||||
- `probe.Measure` performs an HTTP GET and records wall-clock total time
|
- `probe.Measure` performs an HTTP GET and records wall-clock total time
|
||||||
|
|||||||
@@ -91,7 +91,7 @@ https://example.com (5 samples)
|
|||||||
|------|---------|--------|
|
|------|---------|--------|
|
||||||
| 0 | Project scaffold — directory structure, `go.mod`, minimal binary | ✅ Done |
|
| 0 | Project scaffold — directory structure, `go.mod`, minimal binary | ✅ Done |
|
||||||
| 1 | Simple total latency — single URL, wall-clock time | ✅ 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 |
|
| 3 | Multiple URLs + `--count`/`-n` — min/avg/max aggregates | ⬜ Pending |
|
||||||
| 4 | `--json` output flag | ⬜ Pending |
|
| 4 | `--json` output flag | ⬜ Pending |
|
||||||
|
|
||||||
|
|||||||
80
docs/usage/step-2-phase-breakdown.md
Normal file
80
docs/usage/step-2-phase-breakdown.md
Normal file
@@ -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> [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.
|
||||||
@@ -2,8 +2,11 @@
|
|||||||
package probe
|
package probe
|
||||||
|
|
||||||
import (
|
import (
|
||||||
|
"context"
|
||||||
|
"crypto/tls"
|
||||||
"io"
|
"io"
|
||||||
"net/http"
|
"net/http"
|
||||||
|
"net/http/httptrace"
|
||||||
"time"
|
"time"
|
||||||
)
|
)
|
||||||
|
|
||||||
@@ -30,14 +33,46 @@ type Result struct {
|
|||||||
Err error
|
Err error
|
||||||
}
|
}
|
||||||
|
|
||||||
// Measure performs an HTTP GET to url and returns a Result.
|
// Measure performs an HTTP GET to url and returns a Result with all phases
|
||||||
// In Step 1 only the Total phase is populated.
|
// populated via net/http/httptrace.
|
||||||
func Measure(url string) Result {
|
func Measure(url string) Result {
|
||||||
r := Result{URL: url}
|
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 {
|
if err != nil {
|
||||||
r.Err = err
|
r.Err = err
|
||||||
r.Total = Phase{Duration: time.Since(start), Present: true}
|
r.Total = Phase{Duration: time.Since(start), Present: true}
|
||||||
@@ -46,11 +81,30 @@ func Measure(url string) Result {
|
|||||||
defer resp.Body.Close()
|
defer resp.Body.Close()
|
||||||
|
|
||||||
_, err = io.Copy(io.Discard, resp.Body)
|
_, err = io.Copy(io.Discard, resp.Body)
|
||||||
|
end := time.Now()
|
||||||
|
|
||||||
r.Total = Phase{Duration: time.Since(start), Present: true}
|
|
||||||
r.StatusCode = resp.StatusCode
|
r.StatusCode = resp.StatusCode
|
||||||
if err != nil {
|
if err != nil {
|
||||||
r.Err = err
|
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
|
return r
|
||||||
}
|
}
|
||||||
|
|||||||
39
go/main.go
39
go/main.go
@@ -4,7 +4,7 @@ import (
|
|||||||
"flag"
|
"flag"
|
||||||
"fmt"
|
"fmt"
|
||||||
"os"
|
"os"
|
||||||
"time"
|
"strings"
|
||||||
|
|
||||||
"latprobe/internal/probe"
|
"latprobe/internal/probe"
|
||||||
)
|
)
|
||||||
@@ -44,17 +44,48 @@ func main() {
|
|||||||
_ = count
|
_ = count
|
||||||
|
|
||||||
failed := false
|
failed := false
|
||||||
for _, url := range urls {
|
for i, url := range urls {
|
||||||
|
if i > 0 {
|
||||||
|
fmt.Println()
|
||||||
|
}
|
||||||
r := probe.Measure(url)
|
r := probe.Measure(url)
|
||||||
if r.Err != nil {
|
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
|
failed = true
|
||||||
continue
|
continue
|
||||||
}
|
}
|
||||||
fmt.Printf("%-45s %d %v\n", r.URL, r.StatusCode, r.Total.Duration.Round(time.Millisecond))
|
printResult(r)
|
||||||
}
|
}
|
||||||
|
|
||||||
if failed {
|
if failed {
|
||||||
os.Exit(1)
|
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
|
||||||
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user