Go httptrace 怎么定位 HTTP 请求慢：DNS、连接复用与 TLS 分段证据

线上接口的总耗时从 80 毫秒涨到 900 毫秒时，先别急着把超时参数调大。对 Go HTTP 客户端来说，这 820 毫秒可能花在 DNS、TCP 建连、TLS 握手、等待响应头，甚至只是连接没有复用；只看 `time.Since(start)`，看不出真正的卡点。

用 httptrace 拆分请求全链路耗时，能精准定位到 DNS 解析、TCP 建连、TLS 握手、服务端首字节等独立阶段，搭配连接复用字段的状态标记，完全不用靠猜就能把慢请求的卡点找出来。

先把“请求慢”拆成一条时间线

Go 的 `net/http` 已经提供了不少计时钩子，入口是 `net/http/httptrace` 包。它不会改变请求流程，只是在关键节点回调，让我们知道某个阶段何时开始、何时结束。最小的观测范围通常包括：

• DNSStart / DNSDone：域名解析是否拖慢首包。
• ConnectStart / ConnectDone：是否真的新建了 TCP 连接。
• TLSHandshakeStart / TLSHandshakeDone：HTTPS 握手耗时和失败原因。
• GotConn：连接来自空闲池，还是刚刚创建。
• GotFirstResponseByte：服务端开始返回数据的时刻。

这些时间点要挂到请求上下文上，而不是在 Transport 外面另起一套猜测逻辑。

用 ClientTrace 记录每一段耗时

下面的示例保留了每个阶段的开始时间，并在请求结束后统一输出。示例 URL 使用占位地址，接入项目时替换成自己的上游服务即可。

package main

import (
    "context"
    "crypto/tls"
    "fmt"
    "net/http"
    "net/http/httptrace"
    "time"
)

func main() {
    var began time.Time
    marks := make(map[string]time.Time)
    trace := &httptrace.ClientTrace{
        DNSStart: func(httptrace.DNSStartInfo) { marks["dns_start"] = time.Now() },
        DNSDone: func(httptrace.DNSDoneInfo) { marks["dns_done"] = time.Now() },
        ConnectStart: func(_, _ string) { marks["connect_start"] = time.Now() },
        ConnectDone: func(_, _, _ string, _ error) { marks["connect_done"] = time.Now() },
        TLSHandshakeStart: func() { marks["tls_start"] = time.Now() },
        TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { marks["tls_done"] = time.Now() },
        GotConn: func(info httptrace.GotConnInfo) {
            fmt.Printf("reused=%v idle=%v was_idle=%v\\n", info.Reused, info.WasIdle, info.IdleTime)
        },
        GotFirstResponseByte: func() { marks["first_byte"] = time.Now() },
    }

    req, _ := http.NewRequest(http.MethodGet, "https://api.example.com/health", nil)
    began = time.Now()
    req = req.WithContext(httptrace.WithClientTrace(context.Background(), trace))
    resp, err := http.DefaultClient.Do(req)
    if err != nil {
        fmt.Println("request failed:", err)
        return
    }
    defer resp.Body.Close()
    fmt.Printf("status=%d total=%s\\n", resp.StatusCode, time.Since(began))
    for _, name := range []string{"dns_start", "dns_done", "connect_start", "connect_done", "tls_start", "tls_done", "first_byte"} {
        if t, ok := marks[name]; ok {
            fmt.Printf("%s +%s\\n", name, t.Sub(began))
        }
    }
}

生产代码建议把回调统一写入一个结构体，再由日志层输出；每个请求都要拥有自己的采集状态，避免并发请求共享一个可变 map。

从回调结果判断到底卡在哪里

一次请求出现总耗时升高，不等于所有阶段都变慢。可以先按下面的证据对照：

这里要特别注意 DNS 回调可能根本不触发。若连接直接从空闲池取出，说明这次请求没有走解析和建连路径，不能把“没有 DNS 耗时”误判为采集失败。

GotConn 是连接复用是否生效的分界线

GotConnInfo.Reused=true 表示 Transport 复用了已有连接；WasIdle=true 还说明它来自空闲连接池。反过来，连续看到 Reused=false，才值得继续检查连接为什么反复新建。

复查时至少记录四个字段：目标主机、Reused、WasIdle、IdleTime。如果响应体没有关闭，或者读取没有完成，连接无法正常回池，下一次请求就可能重新建连。这个问题和 DNS 慢看起来相似，但证据完全不同。

把采集逻辑放进可关闭的诊断开关

httptrace 回调适合排查，不适合无条件把所有时间点写成高基数字段。实践中可以给指定上游或抽样请求打开诊断，并在日志中加入 request_id、host、status、total_ms 和阶段耗时。

type PhaseCost struct {
    DNSMS     int64
    ConnectMS int64
    TLSMS     int64
    FirstByteMS int64
    Reused    bool
}

诊断完成后，先用同一目标连续请求几次：第一次通常更容易暴露 DNS、TCP 和 TLS 成本，后续请求则能观察连接池是否稳定。不要拿第一次的冷连接数据和后续热连接数据混成一个平均值。

常见问题：httptrace 排查慢请求的几个边界

httptrace 能直接告诉我服务端处理了多久吗？

不能。它能测到客户端收到第一个响应字节前的时间，里面包含网络等待和服务端处理，但不能单独拆出服务端内部耗时，需要结合上游 trace id 或服务端日志。

连接复用时为什么没有 DNS 和 TLS 时间？

因为这次请求直接拿到了已有连接，解析、TCP 建连和 TLS 握手都发生在更早的时刻。看 `GotConn` 的复用字段即可确认这条路径。

请求失败时还需要关闭 Response.Body 吗？

只有拿到非空响应时才关闭 `Body`。如果返回错误且响应为空，不要对空对象调用关闭方法；同时保留错误文本和阶段回调，便于判断失败发生在哪一步。

httptrace 是否能替代超时配置？

不能。httptrace 负责观察，context、Transport 和 Client 的超时负责限制等待时间。先用观测确定卡点，再按阶段设计等待时长。

最后用一张清单收口

• 是否区分了冷连接和连接复用请求？
• 是否记录了 DNS、Connect、TLS、首字节和总耗时？
• 是否同时保留了目标主机、状态码、错误和 request_id？
• 是否确认 Response.Body 能正常关闭并回收连接？
• 修复后是否用同一目标连续请求，复查阶段耗时是否真的下降？

把“请求慢”拆成时间线之后，排查就从猜参数变成看证据：DNS 问题找解析链路，建连问题找网络和连接池，首字节慢则回到上游服务本身。`httptrace` 的价值不在于产出更多日志，而在于让每一次调优都有可复查的分段依据。