Go httptrace.ClientTrace 怎么定位连接复用：DNS、TLS 与首字节耗时

Go 服务调用偶发变慢时，先别急着把超时时间整体调大。一次 HTTP 请求的总耗时可能卡在 DNS、TCP 建连、TLS 握手、等待响应头中的任一段；如果连接已经复用，前面几段甚至不会重新发生。net/http/httptrace 的 ClientTrace 可以把这些阶段挂到请求上下文里，帮助你把“慢”拆成可判断的证据。

排查的关键不是记录更多日志，而是记录每个阶段的开始和结束，并用 GotConnInfo.Reused 区分复用连接与新连接。

先把一次请求拆成几个时间段

诊断代码应围绕同一个 http.Request 建立时间线。常用节点包括获取连接、DNS、TCP、TLS、写请求、收到首字节和请求结束。不要在每个回调里打印一行无关联字符串，否则高并发日志很快会失去上下文。

下面的辅助函数保留请求开始时间，并在回调中只记录阶段耗时。示例没有把响应正文写进日志，适合先放在问题复现或低采样率诊断路径里。

type phaseClock struct {
    start time.Time
    mark  map[string]time.Time
}

func (c *phaseClock) at(name string) {
    c.mark[name] = time.Now()
}

func (c *phaseClock) elapsed(name string) time.Duration {
    if t, ok := c.mark[name]; ok {
        return t.Sub(c.start)
    }
    return 0
}

最小可用写法：把 ClientTrace 放进请求上下文

httptrace.WithClientTrace 返回一个带追踪信息的新上下文，随后要用这个上下文构造请求或替换请求上下文。常见错误是先执行了请求，再临时创建 trace；那样回调不会追溯已经发生的阶段。

func do(ctx context.Context, client *http.Client, rawURL string) error {
    clock := &phaseClock{start: time.Now(), mark: make(map[string]time.Time)}
    trace := &httptrace.ClientTrace{
        GetConn: func(hostPort string) {
            clock.at("get_conn")
        },
        GotConn: func(info httptrace.GotConnInfo) {
            clock.at("got_conn")
            log.Printf("got_conn reused=%t was_idle=%t idle=%s",
                info.Reused, info.WasIdle, info.IdleTime)
        },
        DNSStart: func(info httptrace.DNSStartInfo) {
            clock.at("dns_start")
        },
        DNSDone: func(info httptrace.DNSDoneInfo) {
            clock.at("dns_done")
            log.Printf("dns_done err=%v addrs=%d", info.Err, len(info.Addrs))
        },
        ConnectStart: func(_, _ string) {
            clock.at("connect_start")
        },
        ConnectDone: func(_, _ string, err error) {
            clock.at("connect_done")
            log.Printf("connect_done err=%v", err)
        },
        TLSHandshakeStart: func() { clock.at("tls_start") },
        TLSHandshakeDone: func(_ tls.ConnectionState, err error) {
            clock.at("tls_done")
            log.Printf("tls_done err=%v", err)
        },
        GotFirstResponseByte: func() { clock.at("first_byte") },
    }

    req, err := http.NewRequestWithContext(
        httptrace.WithClientTrace(ctx, trace), http.MethodGet, rawURL, nil,
    )
    if err != nil {
        return err
    }
    resp, err := client.Do(req)
    if err != nil {
        return err
    }
    defer resp.Body.Close()
    _, err = io.Copy(io.Discard, resp.Body)
    return err
}

这里的 GotConn 是第一处重要判断点：Reused=true 表示本次请求拿到了已有连接，通常不会再次触发 DNS、TCP 或 TLS 回调。WasIdle 和 IdleTime 还能帮助发现连接在池里闲置过久后被服务端或中间设备关闭的情况。

从回调结果判断到底是哪一段慢

DNS 到连接建立

如果 DNSStart 到 DNSDone 的差值明显升高，先检查解析器、搜索域、IPv6 选择和本机网络环境。不能只看 DNSDoneInfo.Addrs 数量；多个地址并不表示每个地址都真正建立了连接。

连接阶段要配合 ConnectStart、ConnectDone 的网络地址看。若 ConnectDone 带错误，当前请求可能还会尝试其他地址，日志应带上请求 ID，避免把失败尝试误当成最终连接结果。

TLS 握手到首字节

HTTPS 请求中，TLS 阶段增长通常与证书链、握手往返或代理有关。握手结束到 GotFirstResponseByte 的等待包含服务端排队、应用处理、代理转发和网络传输，适合命名为“首字节等待”，不要写成“后端执行耗时”。

如果首字节很快但读取正文很慢，问题就不在首字节前的阶段，应该继续看响应体大小、服务端流式输出和客户端读取速度。

连接复用时为什么看不到 DNS 和 TLS

Transport 会维护空闲连接池。复用命中后，请求直接从连接开始写入，阶段时间线自然比新连接短。此时不要把“没有 DNS 日志”当作埋点失效，而要把 GotConnInfo.Reused 一起写进指标或结构化日志。

type TraceResult struct {
    Reused       bool          `json:"reused"`
    WasIdle      bool          `json:"was_idle"`
    IdleTime     time.Duration `json:"idle_time"`
    DNS          time.Duration `json:"dns"`
    Connect      time.Duration `json:"connect"`
    TLS          time.Duration `json:"tls"`
    FirstByte    time.Duration `json:"first_byte"`
    Total        time.Duration `json:"total"`
}

生产上可以按 reused 分组看分位数：复用连接慢，重点看服务端首字节和响应体；新连接慢，才继续细分 DNS、TCP 和 TLS。这个分组比把所有请求混成一条平均耗时曲线更容易定位问题。

上线前的日志和安全边界

回调可能在不同 goroutine 中触发，不能让多个回调无保护地写共享 map。示例为了突出流程省略了锁；真实代码可以给 phaseClock 加 sync.Mutex，或者改成向单独的事件 channel 发送不可变事件。

日志里保留主机名、阶段耗时、复用标记和错误类型即可。不要记录 Cookie、Authorization、完整 URL 查询参数或响应正文。采样率、超时和日志级别应可配置，问题结束后及时关闭高粒度追踪。

相关问题

ClientTrace 能测到服务端执行时间吗？

不能。它记录的是客户端看到的请求生命周期，首字节前的等待还混合了代理、网络和服务端处理。若要拆出服务端执行时间，需要服务端指标或分布式追踪。

为什么同一个请求没有触发 DNSStart？

最常见原因是连接复用或解析结果命中缓存。先检查 GotConnInfo.Reused，再结合 Transport 和网络环境判断，不要为了强行触发回调而在生产环境关闭连接复用。

是否应该每个请求都启用所有回调？

排障阶段可以短时启用；长期运行建议采样，并把事件收敛成结构化字段。高并发下无条件打印每个回调，会让日志本身成为新的性能和成本问题。

收尾：先看复用，再看阶段

httptrace.ClientTrace 的价值在于把总耗时变成可解释的阶段证据。第一步先确认连接是否复用，第二步再看 DNS、连接、TLS 和首字节的相对耗时，最后用服务端和代理侧数据做交叉验证。这样既能避免盲目调大超时，也不会把客户端观测误写成服务端真相。