耗时不准的根本原因是计时终点未锚定在响应实际写出并flush的时刻，而错误地设在handler返回或defer执行时；必须用包装responsewriter在write/writeheader后获取真实状态码、字节数和完成时间。
为什么 http.Handler 包裹日志中间件后耗时不准
直接用 time.Now() 在中间件开头记开始时间、结尾记结束时间，看似合理，但实际记录的耗时往往偏大。根本原因是 Go 的 http.ServeMux 或第三方路由（如 gorilla/mux、chi）可能在中间件执行前/后插入其他逻辑（比如路径匹配、变量解析），而更关键的是：如果 handler 内部调用了 panic 且被 recover 捕获，或写入 response 时遇到连接中断（write: broken pipe），标准的 defer 计时会照常结束，但真实响应并未完成——此时日志里的 “耗时” 对调试没意义。
真正反映用户感知延迟的，是 ResponseWriter 实际写入字节并 flush 的时刻。必须把计时终点锚定在写响应完成之后。
- 不要在
defer中仅靠time.Since(start)计算耗时 - 避免在 handler 返回后才记录日志——此时可能已错过写响应失败的上下文
- 若用
log.Println同步输出，高并发下会成为瓶颈；建议用结构化日志库（如zap）异步写入
如何用自定义 ResponseWriter 拦截写操作并精确计时
核心思路是包装原始 http.ResponseWriter，重写 Write、WriteHeader 和 Flush 方法，在首次写响应头或正文时触发计时结束，并记录状态码与字节数。
下面是一个轻量实现：
type loggingResponseWriter struct {
http.ResponseWriter
statusCode int
written int
start time.Time
}
func (lrw *loggingResponseWriter) WriteHeader(code int) {
lrw.statusCode = code
lrw.ResponseWriter.WriteHeader(code)
}
func (lrw *loggingResponseWriter) Write(b []byte) (int, error) {
if lrw.statusCode == 0 {
lrw.statusCode = http.StatusOK
}
n, err := lrw.ResponseWriter.Write(b)
lrw.written += n
return n, err
}
func (lrw *loggingResponseWriter) Status() int {
return lrw.statusCode
}
func (lrw *loggingResponseWriter) Size() int {
return lrw.written
}
func LoggingMiddleware(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
start := time.Now()
lrw := &loggingResponseWriter{
ResponseWriter: w,
statusCode: 0,
written: 0,
start: start,
}
defer func() {
// 注意：这里不立即打日志！等 Write/WriteHeader 完成后再记
// 真实耗时应以「响应发出」为终点，不是 handler 返回
}()
next.ServeHTTP(lrw, r)
// 此处才是响应真正发出后的时机
duration := time.Since(start)
status := lrw.Status()
size := lrw.Size()
method := r.Method
path := r.URL.Path
log.Printf("[%s] %s %s %d %d %v", method, path, status, size, duration.Microseconds(), r.UserAgent())
})
}
-
WriteHeader被调用时才确定状态码，不能依赖初始值 -
Write可能被多次调用，需累加written字节数 - 务必在
next.ServeHTTP调用之后读取lrw.Status()和lrw.Size()，否则可能为 0
使用 chi 或 gorilla/mux 时怎么接入耗时日志
这些路由器本身支持中间件链式注册，但要注意顺序：耗时日志中间件必须放在最外层（即第一个注册），否则内层中间件 panic 或提前 return 会导致计时不完整。
以 chi 为例：
r := chi.NewRouter()
r.Use(LoggingMiddleware) // 必须放第一行！
r.Get("/api/users", usersHandler)
r.Post("/api/posts", postsHandler)
而 gorilla/mux 需手动包装：
r := mux.NewRouter()
r.HandleFunc("/api/users", usersHandler).Methods("GET")
http.ListenAndServe(":8080", LoggingMiddleware(r))
-
chi的Use是从外向内执行，所以LoggingMiddleware会包裹所有后续 handler - 如果用了认证中间件（如 JWT 验证），它应该在
LoggingMiddleware之后注册，否则 401 耗时会被计入，但你可能只想统计业务逻辑耗时 - 若要区分“框架开销”和“业务耗时”，可在业务 handler 内部再套一层计时，而非全链路统一计时
为什么生产环境别用 log.Printf 打耗时日志
log.Printf 默认同步写文件或 stdout，每条日志都触发系统调用，在 QPS 过千时会明显拖慢吞吐。更严重的是，当日志内容含大量字符串拼接（如 r.UserAgent()、r.RemoteAddr）时，GC 压力陡增。
- 改用
zap.L().Info+zap.String("path", r.URL.Path)等结构化字段，避免 fmt.Sprintf - 对耗时字段，用
zap.Duration("duration", duration)，而非zap.String("duration", duration.String()) - 设置采样（如只记录 >500ms 的请求），或按百分位聚合（P95/P99），而不是每条都记
- 注意：
zap的Syncer默认缓冲 32KB，若日志量突增仍可能阻塞，可调大EncoderConfig.EncodeLevel避免冗余字段
耗时日志真正的难点不在“怎么记”，而在于“什么时候才算真正完成”——只要响应还没离开服务器网卡，就不该关掉计时器。这点容易被忽略，但恰恰决定日志是否可信。
golang免费学习笔记（深入）：立即使用
在学习笔记中，你将探索golang的核心概念和高级技巧！
