Go httptrace DNSStart 怎样定位 DNS 解析耗时

一次 Go HTTP 请求变慢时，单看总耗时只能知道“慢了”，却不知道慢在 DNS、TCP 连接、TLS 握手还是服务端响应。我的做法是先把观测边界拆开：httptrace.ClientTrace 用回调接收客户端请求事件，其中 DNSStart 标记 DNS lookup 开始，DNSDone 标记 lookup 结束，用两次时间记录相减即可得到 DNS 阶段耗时。

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

这段耗时只代表当前请求实际触发的 DNS 查询。若连接来自 HTTP Transport 的空闲连接池，DNS 回调可能不会出现；没有回调不能被当成“DNS 耗时为 0”。

先把 DNS 观测当成请求链中的一个边界

我第一次给慢请求加日志时，最容易犯的错是把请求开始到收到响应的时间全部叫作“网络耗时”。httptrace 的价值在于把这条链拆成若干静态边界：请求上下文承载 ClientTrace，Transport 触发 DNSStart 和 DNSDone，之后才可能进入连接建立、TLS 和响应阶段。

因此，DNS 耗时的定义应当是 DNSDone 时刻减去 DNSStart 时刻，而不是整个 client.Do 的耗时。DNSDoneInfo 还会告诉我们是否有错误、找到哪些地址，以及查询结果是否与并发调用方合并。

把 DNSStart 和 DNSDone 接到同一个请求上下文

下面的写法只记录一个请求的 DNS 区间，同时保留错误信息。锁不是为了让请求变慢，而是因为官方文档明确提醒 ClientTrace 的回调可能由不同 goroutine 并发调用，不能把共享时间变量当成天然安全。

package main

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

func requestWithDNSTiming(ctx context.Context, client *http.Client, target string) error {
    var mu sync.Mutex
    var dnsStart time.Time
    var dnsElapsed time.Duration
    var dnsErr error

    trace := &httptrace.ClientTrace{
        DNSStart: func(info httptrace.DNSStartInfo) {
            mu.Lock()
            // 只记录本次请求的 DNS 起点，不把整个请求时间混进来。
            dnsStart = time.Now()
            mu.Unlock()
        },
        DNSDone: func(info httptrace.DNSDoneInfo) {
            mu.Lock()
            // DNSDone 与 DNSStart 配对，错误也要和耗时一起保留。
            if !dnsStart.IsZero() {
                dnsElapsed = time.Since(dnsStart)
            }
            dnsErr = info.Err
            mu.Unlock()
        },
    }

    req, err := http.NewRequestWithContext(
        httptrace.WithClientTrace(ctx, trace), http.MethodGet, target, nil,
    )
    if err != nil {
        return fmt.Errorf("创建请求失败: %w", err)
    }

    resp, err := client.Do(req)
    if err != nil {
        return fmt.Errorf("发送请求失败: %w", err)
    }
    // 响应体必须关闭，避免影响 Transport 的连接复用。
    defer resp.Body.Close()

    mu.Lock()
    fmt.Printf("status=%s dns=%s dnsErr=%v\n", resp.Status, dnsElapsed, dnsErr)
    mu.Unlock()
    return nil
}

这里的关键不是打印格式，而是把 trace 放进这个请求的 Context。WithClientTrace 返回的新上下文只服务于当前请求，不会修改原来的父上下文。真实项目里可以把打印替换成指标或结构化日志，但应保留“没有 DNS 回调”和“DNSDone 带错误”这两种状态。

连接复用时，为什么看不到 DNS 回调

Transport 有空闲连接池。若本次请求直接拿到可复用连接，DNS 解析可能早已在更早的请求里完成，当前请求自然没有新的 DNSStart/DNSDone 区间。这不是埋点失效，而是观测对象变了：当前请求需要关注的是 GotConnInfo.Reused 和 WasIdle，不能强行补一个 DNS 数字。

我会把结果分成三类：

如果只统计“有回调的请求”的平均值，得到的是 DNS lookup 样本的平均耗时，不是所有 HTTP 请求的平均 DNS 成本。这个口径要在指标名称里说清楚。

补上并发和失败边界

DNS 的数据不是只有一个 duration。DNSDoneInfo.Addrs 是解析得到的地址，Err 是错误，Coalesced 表示结果是否与另一个并发 DNS 查询的调用方共享。它们分别回答“找到了什么”“是否失败”“是否发生查询合并”，不能混成一个成功标志。

还有三个容易被忽略的边界：

• 不要在回调里假设一定有 IPv4；Addrs 可能同时包含 IPv4 和 IPv6 地址。
• 不要把回调顺序扩展成跨重定向的完整链路；ClientTrace 当前描述的是一次 round trip。
• 不要让观测锁包住网络操作；回调只写入小对象，耗时计算和上报可以在请求逻辑之外完成。

最后用一张清单判断指标是否可信

如果我要把这段代码放进服务，我会检查：是否按请求创建 trace；是否记录 DNSStart 缺失；是否保留 DNSDoneInfo.Err 和 Coalesced；是否用独立字段表示“未观测”；是否同时采集连接复用状态；是否在 Response.Body.Close 后维持 Transport 的复用能力。满足这些条件，DNS 指标才不会把缓存连接、解析失败和真正的慢查询混在一起。

相关问题

• 为什么 HTTP 请求很慢但 DNS 耗时很短？通常应继续看连接建立、TLS 或首字节事件。
• DNSDone 没有被调用怎么办？先区分请求是否复用了连接，再检查请求是否在 DNS 阶段前失败。
• Coalesced 为 true 说明 DNS 更快吗？它只说明查询结果被并发调用方共享，不能单独推出耗时结论。