Go httptrace 怎样定位连接建立耗时

我排查 Go HTTP 客户端偶发变慢时，最先做的不是把超时时间调大，而是把一次请求拆成 DNS、连接、TLS、写请求和首字节几个阶段。net/http/httptrace 的 ClientTrace 正好提供这些观测点：把它放进请求的 context 后，就能知道慢在解析、重新建连，还是服务端迟迟没有返回响应头。

httptrace可以直接追踪到DNS解析、TCP握手、TLS协商、连接复用等各个连接建立阶段的精确耗时，不需要额外引入第三方APM埋点库，原生零侵入就能拿到完整的网络链路明细数据。

先用钩子拆出请求的关键时间段

先准备一组阶段时间。示例用 time.Now() 记录事件，time.Time 的差值会使用单调时钟部分，适合计算同一进程内的耗时。DNS、连接和首字节回调分别写入起止值；某个阶段失败时保留错误，而不是把它当成 0 毫秒。

把复用连接和新建连接分开统计

GotConn 是判断连接池的关键。Reused=true 表示本次请求拿到的连接之前已经使用过，WasIdle=true 还能说明它来自空闲连接池。此时通常不会重新触发完整的 DNS、Connect 和 TLS 链路，所以不要用“总耗时减掉首字节”来猜建连耗时。

用完整示例输出可解释的耗时结果

下面的最小客户端请求一个 HTTPS 地址，把关键阶段统一换算成毫秒。图和输出都是文章说明用的结构，不是某次线上请求的运行截图；实际接入时可以把这些数字写入结构化日志，并加入 URL 主机、状态码和请求 ID。

package main

import (
    "context"
    "fmt"
    "io"
    "net/http"
    "net/http/httptrace"
    "time"
)

func main() {
    // 用一个起点串起本次请求，阶段时间只用于同一请求内比较。
    started := time.Now()
    var dnsStart, dnsDone, connectStart, connectDone, wroteRequest, firstByte time.Time
    var connectErr error

    trace := &httptrace.ClientTrace{
        DNSStart: func(httptrace.DNSStartInfo) { dnsStart = time.Now() },
        DNSDone: func(info httptrace.DNSDoneInfo) {
            dnsDone = time.Now()
            if info.Err != nil { fmt.Println("dns_error:", info.Err) }
        },
        ConnectStart: func(string, string) { connectStart = time.Now() },
        ConnectDone: func(string, string, err error) {
            connectDone, connectErr = time.Now(), err
        },
        WroteRequest: func(info httptrace.WroteRequestInfo) {
            // 写请求失败时保留错误，便于和首字节缺失区分。
            wroteRequest = time.Now()
            if info.Err != nil { fmt.Println("write_error:", info.Err) }
        },
        GotConn: func(info httptrace.GotConnInfo) {
            // Reused/WasIdle 决定后续是否应该解释为重新建连。
            fmt.Printf("reused=%v was_idle=%v idle=%s\\n", info.Reused, info.WasIdle, info.IdleTime)
        },
        GotFirstResponseByte: func() { firstByte = time.Now() },
    }

    req, err := http.NewRequest(http.MethodGet, "https://example.com/", nil)
    if err != nil { panic(err) }
    req = req.WithContext(httptrace.WithClientTrace(context.Background(), trace))

    resp, err := http.DefaultClient.Do(req)
    if err != nil { panic(err) }
    defer resp.Body.Close() // 及时归还连接，下一次才有机会复用。
    _, _ = io.Copy(io.Discard, resp.Body)

    fmt.Printf("dns_ms=%d connect_ms=%d write_ms=%d first_byte_ms=%d total_ms=%d\\n",
        millis(dnsDone.Sub(dnsStart)), millis(connectDone.Sub(connectStart)),
        millis(wroteRequest.Sub(started)), millis(firstByte.Sub(started)), millis(time.Since(started)))
    if connectErr != nil { fmt.Println("connect_error:", connectErr) }
}

func millis(d time.Duration) int64 {
    // 未触发的阶段会得到 0；生产日志应再配合布尔字段区分缺失与真实 0。
    if d 

这里最容易忽略的是 Response.Body.Close() 和读取响应体。及时关闭并消费响应体有利于 Transport 回收连接；如果只看一次请求的 first_byte_ms，却不记录连接是否复用，后面的对比就没有可比性。

哪些耗时不能直接归因给网络

如果 dns_ms 很大，优先检查解析器、域名配置和运行环境；如果 connect_ms 很大，再看目标地址、代理、IPv6/IPv4 竞争和网络策略。若连接已经复用但 first_byte_ms 仍高，重点转向服务端排队、应用处理、代理转发或响应头生成，而不是继续调 DNS。

还要记住三个边界：ConnectStart 在启用 Happy Eyeballs 时可能触发多次；ClientTrace 当前覆盖单次 round trip，不会替你串起一系列重定向；回调可能从不同 goroutine 调用，多个请求并发时不能把共享变量写成全局状态。真正用于监控时，应为每个请求创建独立的计时器，并把失败事件和复用状态一起输出。

常见问题

为什么看不到 ConnectStart？

最常见原因是连接被 Transport 复用，或请求没有走到新拨号阶段。先看 GotConnInfo.Reused；如果为 true，就把本次请求归入连接复用样本。

GotFirstResponseByte 很慢就是服务端慢吗？

不一定。它包含请求写完后的链路等待、代理处理和服务端处理时间，只能说明首字节尚未到达，还需要结合服务端日志或代理指标继续拆分。

能不能用 httptrace 统计整个重定向链路？

它主要跟踪单次 HTTP 请求与响应的 round trip，没有覆盖一系列重定向的统一钩子。需要完整链路时，应在客户端层为每次请求和重定向记录独立的关联 ID。