Go httptrace.ClientTrace 怎样定位 HTTP 客户端连接阶段耗时

HTTP 客户端总耗时变长时，直接看 time.Since(start) 只能知道“慢了”，不能说明慢在 DNS、建立连接、TLS 握手、发送请求，还是服务端迟迟没有返回首字节。Go 标准库的 net/http/httptrace 提供了一组请求阶段回调，可以把一次 RoundTrip 拆成可解释的时间点。

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

实战中建议先记录 DNSStart/DNSDone、ConnectStart/ConnectDone、TLSHandshakeDone、GotConn、WroteRequest 和 GotFirstResponseByte。再用 GotConnInfo.Reused 判断是否复用了连接，就能把“连接慢”和“服务端响应慢”分开。

先把 ClientTrace 放进请求上下文

ClientTrace 不是单独发送请求的客户端，而是一组由 HTTP Transport 在请求生命周期中触发的钩子。创建好 trace 后，要用 httptrace.WithClientTrace 生成新上下文，再把这个上下文交给请求。

package main

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

func main() {
	// 用一个稳定的起点统一计算各阶段耗时。
	start := time.Now()
	trace := &httptrace.ClientTrace{
		DNSStart: func(info httptrace.DNSStartInfo) {
			fmt.Printf("dns start host=%s at=%s\n", info.Host, time.Since(start))
		},
		DNSDone: func(info httptrace.DNSDoneInfo) {
			fmt.Printf("dns done addrs=%d err=%v at=%s\n", len(info.Addrs), info.Err, time.Since(start))
		},
		GotFirstResponseByte: func() {
			fmt.Printf("first response byte at=%s\n", time.Since(start))
		},
	}

	// WithClientTrace 返回带 trace 的新上下文，不会原地修改父上下文。
	ctx := httptrace.WithClientTrace(context.Background(), trace)
	req, err := http.NewRequestWithContext(ctx, http.MethodGet, "https://example.com/", nil)
	if err != nil {
		fmt.Printf("create request failed: %v\n", err)
		return
	}

	// Client 负责发起请求；响应体由调用方关闭，避免连接无法回收到连接池。
	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		fmt.Printf("request failed: %v\n", err)
		return
	}
	defer resp.Body.Close()
	fmt.Printf("status=%s total=%s\n", resp.Status, time.Since(start))
}

这里的 example.com 只是示例目标，文章重点是回调挂接方式。回调可以在请求失败后触发，也可能在请求已经返回错误时仍有异步回调，因此日志函数应尽量短小，并允许事件顺序在并发环境中交错。

用时间点拆开 DNS、连接和首字节

为了排查连接阶段，推荐把每个回调都映射到同一个 traceClock。不要在回调里直接假设“上一个事件一定成功”，而是记录事件名、相对时间和错误字段，最后再按事件名计算区间。

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

type traceClock struct {
	start time.Time
}

func (c traceClock) mark(name string) {
	// 统一输出相对时间，便于把多次请求放到同一份日志中比较。
	fmt.Printf("event=%s elapsed=%s\n", name, time.Since(c.start))
}

func newTrace(clock traceClock) *httptrace.ClientTrace {
	return &httptrace.ClientTrace{
		DNSStart: func(info httptrace.DNSStartInfo) {
			clock.mark("dns.start:" + info.Host)
		},
		DNSDone: func(info httptrace.DNSDoneInfo) {
			// Err 只表示 DNS 阶段的结果，不等于整个请求失败原因。
			clock.mark(fmt.Sprintf("dns.done err=%v", info.Err))
		},
		ConnectStart: func(network, addr string) {
			clock.mark("connect.start:" + network + ":" + addr)
		},
		ConnectDone: func(network, addr string, err error) {
			// Dual Stack 可能触发多次连接尝试，所以不能假设只出现一次。
			clock.mark(fmt.Sprintf("connect.done %s %s err=%v", network, addr, err))
		},
		TLSHandshakeDone: func(_ tls.ConnectionState, err error) {
			clock.mark(fmt.Sprintf("tls.done err=%v", err))
		},
		WroteRequest: func(info httptrace.WroteRequestInfo) {
			clock.mark(fmt.Sprintf("request.wrote err=%v", info.Err))
		},
		GotFirstResponseByte: func() {
			clock.mark("response.first-byte")
		},
	}
}

上面的片段展示回调关系时省略了完整 import；实际文件还需要导入 crypto/tls、fmt、net/http/httptrace 和 time。生产代码可以把事件写进结构化日志，不建议在高并发请求里拼接很长的字符串。

GotConnInfo 怎样判断连接是否复用

如果请求偶尔变慢，先看 GotConn 回调提供的 GotConnInfo。其中 Reused 表示连接是否已经被此前的请求使用，WasIdle 表示它是否来自空闲连接池。复用连接时，当前请求通常不会重新经历完整的 DNS、TCP 连接和 TLS 握手阶段。

trace := &httptrace.ClientTrace{
	GotConn: func(info httptrace.GotConnInfo) {
		// Reused 与 WasIdle 用于区分连接池命中和新建连接。
		fmt.Printf("got-conn reused=%t was-idle=%t idle-time=%s\n",
			info.Reused, info.WasIdle, info.IdleTime)
	},
	PutIdleConn: func(err error) {
		// 返回连接池失败时记录原因，nil 表示成功放回空闲池。
		fmt.Printf("put-idle err=%v\n", err)
	},
}

Reused=false 不能单独证明 DNS 一定慢，它只说明这次没有复用已有连接。还要结合 DNS、Connect 和 TLS 回调的相对时间判断。另一方面，PutIdleConn 在连接放回空闲池时触发，且不适用于禁用 keep-alive 的 Transport。

看到哪些信号时该查哪一层

超时、重定向和并发日志的边界

ClientTrace 当前跟踪的是一次请求响应往返，不会把一系列重定向自动合并成一个完整链路。需要分析重定向时，应给每个请求设置可关联的请求 ID，并在更高层记录最终 URL 和总耗时。

回调可能由不同 goroutine 调用，某些回调也可能在请求失败或响应结束后触发。因此共享累计变量要用锁或原子操作；最简单的做法是让回调只发送不可变事件到一个带缓冲的 channel，再由单独的聚合器计算区间。

如果只看到总超时而没有 GotFirstResponseByte，不要把它解释成“服务端一定没有返回”。可能是连接阶段失败，也可能是请求体发送、代理等待或 Transport 在更早阶段返回错误。最终原因仍应结合 Do 返回的错误和各阶段回调中的 Err 一起判断。

排查结论

1. 先用 WithClientTrace 把 trace 放进请求上下文，确认钩子确实属于这一次请求。
2. 记录 DNS、Connect、TLS、WroteRequest、GotConn 和首字节事件，不要只记总耗时。
3. 用 GotConnInfo.Reused 与 WasIdle 判断连接池命中，再解释缺失的阶段回调。
4. 把回调当作并发事件处理；重定向、重试和超时要在上层建立请求 ID 与最终结论。

相关问题：为什么连接复用后没有 DNS 回调？
因为本次请求可能直接从 Transport 的空闲连接池取得连接，未发生新的解析阶段。如何确认 TLS 是否拖慢请求？
同时记录 GotConn 和 TLSHandshakeDone，并区分复用连接与新建连接。为什么回调日志顺序看起来不连续？
回调可能在不同 goroutine 中执行，日志系统也可能异步写入，应使用相对时间和请求 ID 排序。