Go 怎样用 httptrace 拆分一次请求的连接耗时

Go 的 net/http 客户端只告诉你请求成功或失败，但一次慢请求可能卡在 DNS、TCP 连接、TLS 握手、发送请求，或者服务端迟迟没有返回首字节。要拆开这些阶段，可以给请求上下文绑定 httptrace.ClientTrace，在回调里记录时间点，再用相邻时间点相减得到阶段耗时。

先把一次 HTTP 请求拆成可解释的时间点

这篇文章只关注单次请求的阶段采集，不接入监控平台，也不讨论全链路追踪。建议先定义一组零值可用的时间字段：请求开始时间、DNS 开始与结束、连接开始与结束、TLS 开始与结束、写请求完成、拿到连接、首字节到达。某个阶段没有发生时，对应字段保持零值，避免把“连接复用”误报为连接耗时。

httptrace.ClientTrace 的回调可能从不同 goroutine 触发，所以共享的时间结构不应在回调里做复杂业务。下面的示例只记录时间点，最后在请求返回后统一计算结果。

package main

import (
    "context"
    "crypto/tls" // TLSHandshakeDone 的回调参数类型。
    "fmt"
    "net/http"
    "net/http/httptrace"
    "time"
)

// TraceResult 保存一次请求中可以解释的阶段时间点。
type TraceResult struct {
    Start, DNSStart, DNSEnd       time.Time
    ConnectStart, ConnectEnd      time.Time
    TLSStart, TLSEnd              time.Time
    GotConn, WroteRequest         time.Time
    FirstResponseByte             time.Time
    Reused                         bool
}

func main() {
    result := &TraceResult{}
    started := time.Now()
    result.Start = started

    trace := &httptrace.ClientTrace{
        DNSStart: func(httptrace.DNSStartInfo) { result.DNSStart = time.Now() },
        DNSDone: func(httptrace.DNSDoneInfo) { result.DNSEnd = time.Now() },
        ConnectStart: func(_, _ string) { result.ConnectStart = time.Now() },
        ConnectDone: func(_, _ string, _ error) { result.ConnectEnd = time.Now() },
        TLSHandshakeStart: func() { result.TLSStart = time.Now() },
        TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { result.TLSEnd = time.Now() },
        GotConn: func(info httptrace.GotConnInfo) {
            result.GotConn = time.Now()
            result.Reused = info.Reused
        },
        WroteRequest: func(httptrace.WroteRequestInfo) { result.WroteRequest = time.Now() },
        GotFirstResponseByte: func() { result.FirstResponseByte = time.Now() },
    }

    // 把 trace 放进请求上下文，Transport 才能触发这些回调。
    request, err := http.NewRequestWithContext(
        httptrace.WithClientTrace(context.Background(), trace),
        http.MethodGet,
        "https://example.com/",
        nil,
    )
    if err != nil {
        panic(err)
    }

    response, err := http.DefaultClient.Do(request)
    if err != nil {
        // 连接失败没有统一的失败回调，最终错误仍要保留。
        panic(err)
    }
    defer response.Body.Close() // 读取结束后归还可复用连接。

    fmt.Printf("reused=%v first_byte=%s\\n", result.Reused, result.FirstResponseByte.Sub(result.Start))
}

用 GotConn 区分连接复用和新建连接

最容易误判的是连接耗时。GetConn 在准备取连接前触发，即使连接池里已经有空闲连接也会触发；GotConn 在成功拿到连接后触发。只有新建连接时，才会出现 ConnectStart 与 ConnectDone。因此，GotConnInfo.Reused=true 时不要把 GotConn.Sub(Start) 当成 TCP 建连时间。

如果启用了 IPv6 Happy Eyeballs，同一次连接可能出现多次 ConnectStart/ConnectDone。不要简单地把多次回调覆盖后就宣称“总连接耗时”；更稳妥的做法是记录每次地址尝试，或只把最后的成功事件用于概要字段。

按时间点计算阶段耗时，错误从 Do 返回值补齐

回调主要告诉你“发生了什么”，不负责给出统一的错误结果。连接建立失败没有专门的失败回调，Client.Do 返回的错误才是最终依据。计算时先检查时间点是否为零，再输出有意义的区间：

// elapsed 只在两个事件都发生时计算差值，避免零时间参与运算。
func elapsed(begin, end time.Time) time.Duration {
    if begin.IsZero() || end.IsZero() || end.Before(begin) {
        return 0
    }
    return end.Sub(begin)
}

// 这些字段可直接转成日志属性，也可以交给上层统一采样。
metrics := map[string]time.Duration{
    "dns":     elapsed(result.DNSStart, result.DNSEnd),
    "connect": elapsed(result.ConnectStart, result.ConnectEnd),
    "tls":     elapsed(result.TLSStart, result.TLSEnd),
    "ttfb":    elapsed(result.Start, result.FirstResponseByte),
}

这里的 ttfb 是从请求开始到响应首字节的总等待时间；若要分析“写完请求后服务端处理了多久”，应再记录 WroteRequest，计算 WroteRequest 到 GotFirstResponseByte 的区间。两者不要混用。

常见问题

为什么复用连接时 connect 耗时是 0？

因为连接池直接返回已有连接，没有发生新的 Dial；这是正常结果。应使用 Reused 字段解释该次请求，而不是给连接耗时填一个估算值。

GotFirstResponseByte 能代表接口响应完成吗？

不能。它只说明响应头的首字节已经到达；完整响应仍要在读取并关闭 Body 后才算消费完成。

httptrace 能替代线上监控吗？

不能直接替代。它适合为单次客户端请求提供细粒度阶段数据，线上聚合、采样、告警和跨服务关联仍需要另外的观测方案。