不能直接在handler里用time.Now()记录耗时,因为中间可能return、panic或提前写响应导致结束时间漏记;defer是唯一能保证无论函数如何退出都执行的机制,但必须将start作为参数传入defer闭包以避免捕获错误值,且应封装为统一中间件并配合wrapper ResponseWriter获取真实status和size。

为什么不能直接在 handler 里用 time.Now() 记录耗时
因为 Go 的 HTTP handler 是并发执行的,time.Now() 放在 handler 开头和结尾看似能算出耗时,但一旦中间有 return、panic 或提前写响应(比如流式返回、错误 early exit),就容易漏掉结束时间点。defer 是唯一能保证「无论函数怎么退出都执行」的机制,但要注意它捕获的是定义时的变量值,不是执行时的——所以必须把起始时间传进 defer 闭包里。
- 错误写法:
start := time.Now(); defer log.Printf("cost: %v", time.Since(start))—— 看似没问题,但若 handler 中调用了其他 defer,它们会按栈序执行,而这个日志 defer 可能比实际写响应还早,导致统计不准(尤其用了http.Flusher或 streaming) - 正确姿势:把
start作为参数传入 defer 函数,避免闭包捕获问题 - 更稳妥的做法是把耗时记录逻辑封装成中间件,统一处理,避免每个 handler 重复写
用 http.Handler 中间件统一记录 API 耗时
不要在每个 handler 里手写 defer,而是用标准 http.Handler 接口包装,既干净又可复用。核心是:在 ServeHTTP 开始记 start,在 defer 里算耗时并打日志,且必须等 next.ServeHTTP 完全返回后再执行 defer(即 defer 写在调用之后)。
func TimingMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
start := time.Now()
// 注意:defer 必须放在这行之后,才能确保 next 执行完
defer func() {
cost := time.Since(start)
log.Printf("[API] %s %s %v", r.Method, r.URL.Path, cost)
}()
next.ServeHTTP(w, r)
})
}
- 必须把
defer放在next.ServeHTTP()之前,Go 的 defer 是注册,执行顺序是 LIFO,但触发时机是函数 return 前——所以只要它在调用 next 后面,就能保证 next 完全结束 - 如果用了自定义 ResponseWriter(比如记录状态码),要确保它包裹了原始
w,否则log里的 status 可能拿不到真实值 - 别用
log.Println,建议用结构化日志库如zerolog或zap,方便后续过滤和监控
如何获取真实 HTTP 状态码和响应体大小
原生 http.ResponseWriter 不暴露状态码和写入字节数,直接 defer 里只能打耗时,没法打 status 或 size。必须用 wrapper 实现 http.ResponseWriter 接口,劫持 WriteHeader 和 Write。
Go 配置库,使用 spf13/viper — 分层优先级(flag > env >file > KV > default),提供 BindPFlag/BindPFlags、SetEnvPrefix + SetEnvKeyReplace 等功能。
type responseWriter struct {
http.ResponseWriter
status int
size int
}
func (rw *responseWriter) WriteHeader(code int) {
rw.status = code
rw.ResponseWriter.WriteHeader(code)
}
func (rw *responseWriter) Write(b []byte) (int, error) {
if rw.status == 0 {
rw.status = 200
}
n, err := rw.ResponseWriter.Write(b)
rw.size += n
return n, err
}
- 初始化 wrapper 时要设默认 status=0,因为
WriteHeader可能不被显式调用(此时默认 200) -
Write方法里要先检查status == 0,否则未调用WriteHeader时 status 仍是 0,日志里会显示 0 - 在 middleware 的 defer 里,用
rw.status和rw.size打日志,比只打耗时更有诊断价值
用 zap 替代 log 打结构化日志
原生 log 输出是字符串拼接,难解析、难聚合。换成 zap 后,字段自动序列化,支持 level 控制,还能加 trace ID 关联请求链路。
立即学习“go语言免费学习笔记(深入)”;
defer func() {
cost := time.Since(start)
logger.Info("api_timing",
zap.String("method", r.Method),
zap.String("path", r.URL.Path),
zap.Int("status", rw.status),
zap.Int("size", rw.size),
zap.Duration("cost", cost),
zap.String("user_agent", r.UserAgent()),
)
}()
- 别用
zap.Any传耗时,要用zap.Duration,否则 JSON 里变成纳秒整数,不方便前端或 Grafana 展示 - 如果项目已用
context传递 trace ID(比如通过X-Request-ID),记得从r.Context()里取出来一起打进去 -
zap默认是 development mode,上线前务必用zap.NewProduction(),否则日志体积暴涨
Write 方法没处理 io.ErrShortWrite 这类部分写入错误,导致 size 统计偏小;还有 panic 情况下,defer 会执行,但若 panic 发生在 next.ServeHTTP 里,wrapper 的 status 可能还是 0——得配合 recover 补充设置。这些边界情况不测,线上看到一堆 0ms / 0B / status 0 的日志就很难受。

















