Go httptrace 入门:看清一次 HTTP 请求慢在哪里

用 httptrace 观察 Go HTTP 客户端请求的 DNS、连接、TLS 和首字节耗时,帮助初学者定位外部接口慢的问题。

写 Go 服务时,调用外部接口慢是很常见的问题。日志里只看到“请求花了 2 秒”,但这 2 秒到底花在哪里?是 DNS 慢、建立连接慢、TLS 握手慢、服务端处理慢,还是响应体下载慢?如果只能靠猜,排查会很痛苦。

Go 标准库的 net/http/httptrace 可以把一次 HTTP 客户端请求拆成多个阶段观察。它不是线上监控系统,但在本地调试、预发排查和定位某个外部依赖时非常有用。本文用一个小函数讲清楚基本用法。

普通请求只能看到总耗时

很多代码会这样记录:

func Fetch(ctx context.Context, url string) error {
	start := time.Now()
	req, err := http.NewRequestWithContext(ctx, http.MethodGet, url, nil)
	if err != nil {
		return err
	}
	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		return err
	}
	defer resp.Body.Close()
	_, _ = io.Copy(io.Discard, resp.Body)
	log.Printf("fetch url=%s cost=%s", url, time.Since(start))
	return nil
}

这能知道总耗时,但不知道阶段。外部接口慢的时候,总耗时只是入口信息,不足以指导优化。如果 DNS 解析慢,应该看 DNS 和网络;如果首字节慢,更多是对方服务端处理或排队;如果响应体慢,可能是数据太大或带宽问题。

加入 httptrace

httptrace.ClientTrace 可以挂到请求 context 上:

func FetchWithTrace(ctx context.Context, rawURL string) error {
	var start, dnsStart, connStart, tlsStart time.Time

	trace := &httptrace.ClientTrace{
		DNSStart: func(info httptrace.DNSStartInfo) {
			dnsStart = time.Now()
			log.Printf("dns start host=%s", info.Host)
		},
		DNSDone: func(info httptrace.DNSDoneInfo) {
			log.Printf("dns done cost=%s addrs=%v err=%v", time.Since(dnsStart), info.Addrs, info.Err)
		},
		ConnectStart: func(network, addr string) {
			connStart = time.Now()
			log.Printf("connect start network=%s addr=%s", network, addr)
		},
		ConnectDone: func(network, addr string, err error) {
			log.Printf("connect done cost=%s err=%v", time.Since(connStart), err)
		},
		TLSHandshakeStart: func() {
			tlsStart = time.Now()
			log.Println("tls start")
		},
		TLSHandshakeDone: func(state tls.ConnectionState, err error) {
			log.Printf("tls done cost=%s err=%v", time.Since(tlsStart), err)
		},
		GotFirstResponseByte: func() {
			log.Printf("first byte cost=%s", time.Since(start))
		},
	}

	start = time.Now()
	ctx = httptrace.WithClientTrace(ctx, trace)
	req, err := http.NewRequestWithContext(ctx, http.MethodGet, rawURL, nil)
	if err != nil {
		return err
	}
	resp, err := http.DefaultClient.Do(req)
	if err != nil {
		return err
	}
	defer resp.Body.Close()
	_, _ = io.Copy(io.Discard, resp.Body)
	log.Printf("total cost=%s", time.Since(start))
	return nil
}

这段代码会输出 DNS、连接、TLS、首字节和总耗时。不是每次请求都会触发所有事件。比如连接复用时,可能不会重新 DNS 和 TLS。这本身也是重要信息:如果连接复用正常,慢点就更可能在服务端处理或响应体阶段。

看懂几个阶段

DNS 阶段慢,通常和域名解析、DNS 服务、网络环境有关。连接阶段慢,可能是网络不通、跨区域延迟、对方端口拥塞。TLS 阶段慢,可能是握手成本、证书链或网络抖动。首字节慢,表示请求已经发出,但迟迟没有收到响应头,常见原因是对方服务处理慢或排队。

如果总耗时很长,但首字节很快,问题可能在读取响应体。比如下载一个很大的 JSON,或者对方分块慢慢返回。此时优化方向可能是分页、压缩、减少字段,而不是盯着连接池。

配合超时使用

trace 只是观察,不能替代超时。客户端仍然应该设置超时:

client := &http.Client{
	Timeout: 5 * time.Second,
}

更细的服务可以使用自定义 Transport

transport := &http.Transport{
	MaxIdleConns:        100,
	MaxIdleConnsPerHost: 10,
	IdleConnTimeout:     90 * time.Second,
	TLSHandshakeTimeout:  5 * time.Second,
}
client := &http.Client{Transport: transport, Timeout: 10 * time.Second}

如果 trace 发现每次都在重新建连接,就要检查是否复用了同一个 client,是否正确读取并关闭响应体。每次请求都新建 http.Client 通常不是好习惯。

不要长期打印过细日志

httptrace 输出很细,适合临时排查,不适合高频接口长期全量打印。你可以只在 debug 模式开启,或者只对某个请求 ID 开启。日志太多会影响性能,也会让真正重要的信息被淹没。

一种简单做法是:

if cfg.EnableHTTPTrace {
	ctx = httptrace.WithClientTrace(ctx, trace)
}

生产环境如果需要长期观测,更适合用指标系统记录阶段耗时,或者在网关、客户端库里做采样。入门阶段先会用 trace 定位问题,已经很有价值。

和连接池问题一起看

很多“偶发慢请求”最后会和连接池有关。比如响应体没有读完或没有关闭,连接无法复用,后续请求就不得不重新建连接。trace 里如果频繁看到 ConnectStartTLSHandshakeStart,就要检查调用代码:

resp, err := client.Do(req)
if err != nil {
	return err
}
defer resp.Body.Close()
_, _ = io.Copy(io.Discard, resp.Body)

如果业务只关心状态码,也仍然建议把 body 读完或明确关闭。对小响应来说,读到 io.Discard 成本很低,却能帮助连接复用。大响应则要看场景,不能为了复用把几 GB 数据都读完。

排查时可以把 trace 日志和请求 ID 放在一起。一次慢请求有唯一 ID,trace 里有阶段耗时,业务日志里有接口和参数范围,几类信息合在一起才容易形成判断。不要只截一行 total cost=2s 就开始改代码。

小结

httptrace 能帮你看清一次 Go HTTP 客户端请求的 DNS、连接、TLS、首字节等阶段。它适合定位“外部接口为什么慢”,尤其是在总耗时日志无法说明原因时。

排查时先加总超时,再用 trace 分阶段观察。看到数据后再决定优化方向:连接复用、DNS、TLS、服务端处理、响应体大小,分别对应不同解法。性能问题不要靠猜,先把请求过程照亮。

继续阅读

探索更多技术文章

浏览归档,发现更多关于系统设计、工具链和工程实践的内容。

全部文章 返回首页