Go httptrace.ClientTrace 怎样区分 DNS 与连接建立耗时

如果你只在 http.Client.Do 外层计时，看到的只是一次请求的总耗时，无法回答“慢在 DNS，还是慢在建立连接”。Go 的 net/http/httptrace 可以把一次 round trip 中的关键客户端事件暴露出来。本文只围绕 DNSStart、DNSDone、ConnectStart 和 ConnectDone 解释计时边界。

官方地址：https://pkg.go.dev/net/http/httptrace

先记住三个判断：DNS 耗时用 DNSDone - DNSStart；新连接的拨号耗时用同一轮 ConnectDone - ConnectStart；如果 GotConnInfo.Reused 为 true，这次请求可能根本没有发生新的连接建立。

四个回调分别覆盖什么时间

DNSStart 表示 DNS 查询开始，DNSDone 表示查询结束，后者还携带地址、错误和是否与其他调用合并的信息。ConnectStart 表示一次新的 Dial 开始，ConnectDone 表示这次 Dial 完成并带有错误结果。

因此，DNS 区间和连接区间是两个不同阶段，不能把所有回调当作一个线性队列。启用 Happy Eyeballs 时，连接回调可能出现多组，甚至由不同 goroutine 并发触发；统计时要按一次 network + addr 的配对保存，而不是使用一个全局“连接开始时间”。

把 trace 绑定到单个请求

使用 httptrace.WithClientTrace 把 trace 放进本次请求的上下文，回调只服务于这一次 round trip。下面的示例用互斥锁保护一个请求级记录器，并在回调中保留配对信息；代码只展示采集方式，不把示例输出当成运行证据。

package main

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

type requestTiming struct {
    mu        sync.Mutex // 回调可能并发执行，按请求保护记录
    dnsStart  time.Time
    dnsCost   time.Duration
    connStart map[string]time.Time // 同时保存不同 network/addr 的拨号开始时间
    connCost  map[string]time.Duration
}

func traceRequest(ctx context.Context) (*requestTiming, context.Context) {
    t := &requestTiming{connStart: make(map[string]time.Time), connCost: make(map[string]time.Duration)}
    trace := &httptrace.ClientTrace{
        DNSStart: func(httptrace.DNSStartInfo) {
            t.mu.Lock()
            defer t.mu.Unlock() // 只在更新当前请求记录后解锁
            t.dnsStart = time.Now()
        },
        DNSDone: func(httptrace.DNSDoneInfo) {
            t.mu.Lock()
            defer t.mu.Unlock()
            if !t.dnsStart.IsZero() { // 没有开始回调时不虚构耗时
                t.dnsCost = time.Since(t.dnsStart)
            }
        },
        ConnectStart: func(network, addr string) {
            t.mu.Lock()
            defer t.mu.Unlock()
            t.connStart[network+"|"+addr] = time.Now()
        },
        ConnectDone: func(network, addr string, err error) {
            t.mu.Lock()
            defer t.mu.Unlock()
            key := network + "|" + addr
            if start, ok := t.connStart[key]; ok && err == nil { // 只记录成功拨号的耗时
                t.connCost[key] = time.Since(start)
            }
        },
    }
    return t, httptrace.WithClientTrace(ctx, trace)
}

func main() {
    timing, ctx := traceRequest(context.Background())
    req, err := http.NewRequestWithContext(ctx, http.MethodGet, "https://example.com", nil)
    if err != nil {
        panic(err) // 示例中直接终止，生产代码应返回或包装错误
    }
    resp, err := http.DefaultClient.Do(req)
    if err != nil {
        panic(err)
    }
    defer resp.Body.Close() // 释放响应体，便于 Transport 复用连接
    timing.mu.Lock()
    fmt.Println("DNS:", timing.dnsCost, "connections:", timing.connCost)
    timing.mu.Unlock()
}

连接复用时不要把“没有回调”当成异常

ClientTrace.GotConn 会告诉你拿到的连接是否复用。连接来自 idle pool 时，GotConnInfo.Reused 为 true，本次请求没有对应的新建 TCP 连接；这时连接建立耗时应标记为“不适用”，而不是填成零后参与平均值。

另一方面，回调函数可能在不同 goroutine 中执行，也可能在请求结束后仍有回调发生。记录器应该属于单个请求，并用锁、通道或其他并发安全结构写入。不要把 DNS 开始时间放在全局变量中，否则并发请求会互相覆盖。

用分段结果定位真正的慢点

最后检查两件事：第一，按请求保存每个阶段，不要用进程级单例；第二，统计连接耗时时保留复用标记、地址和错误。这样输出的“DNS 慢”或“连接慢”才有明确的边界，而不是一条无法解释的总耗时。

相关问题

为什么设置了 ClientTrace 却没有 DNSStart？

这次请求可能复用了已有连接，或者底层路径没有触发新的 DNS 查询。应结合 GotConnInfo.Reused 和请求错误一起判断。

ConnectStart 为什么可能出现多次？

网络栈可能并行尝试不同地址。应按回调参数建立独立记录，并接受回调并发，而不是假设整个请求只有一条连接候选。