写 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 里如果频繁看到 ConnectStart 和 TLSHandshakeStart,就要检查调用代码:
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、服务端处理、响应体大小,分别对应不同解法。性能问题不要靠猜,先把请求过程照亮。
继续阅读
探索更多技术文章
浏览归档,发现更多关于系统设计、工具链和工程实践的内容。