Revel中间件耗时统计需在调用filterChain[0]前后精准记录time.Now(),并包装ResponseWriter获取真实状态码和响应大小,避免defer、末尾计时或依赖c.Response字段。

Revel 中间件里怎么打准确的耗时时间点
Revel 的 Filter 是函数类型 func(c *Controller, filterChain []Filter),它不像 Express 或 Gin 那样有明确的「进入 handler 前/后」钩子,而是靠手动调用 filterChain[0](c, filterChain[1:]) 控制流程。所以计时必须放在调用下游 filter 前后——不能依赖 defer,也不能把 time.Now() 放在 filter 函数末尾。
常见错误是写成这样:
func TimingFilter(c *Controller, fc []Filter) {
start := time.Now()
if len(fc) > 0 {
fc[0](c, fc[1:])
}
// ❌ 这里不是响应完成时刻:可能还没写 header/body,也可能 panic 后被 PanicFilter 拦截
log.Printf("took %v", time.Since(start))
}
正确姿势是:在调用下一个 filter 前记开始时间,调用返回后立刻记结束时间,并确保这个「调用→返回」包裹了整个请求处理链(包括 Controller.Action 执行):
-
start := time.Now()必须紧挨着fc[0](c, fc[1:])前一行 - 结束后立即用
time.Since(start),中间不插入任何日志格式化、状态码判断等逻辑 - 如果
len(fc) == 0,说明已到链尾(即 ActionInvoker),此时应直接执行c.Render()或类似逻辑,也要包进计时范围
为什么不能直接读 c.Response.StatusCode 或用 c.Result 判断状态
Revel 的 *Controller 没有暴露底层 http.ResponseWriter,c.Response 是个简化包装,c.Response.Status 和 c.Response.Size 在 filter 中始终为 0 或默认值——因为真实写入发生在 Action 执行完、模板渲染后,而那时 filter 已退出。
想拿到真实状态码和响应字节数,必须包装原始 ResponseWriter。Revel 不像 Echo 或 Gin 提供 WrapResponseWriter 工具,得自己实现一个嵌入 http.ResponseWriter 的结构体,在 WriteHeader 和 Write 中更新字段。否则你日志里的 status 总是 200,size 总是 0。
- 别尝试从
c.Result类型断言获取状态:它可能是*revel.JsonResult、*revel.TextResult等,类型不稳定 - 如果只关心「是否出错」,可检查
c.Flash.Error或c.Validation.HasErrors(),但这只是业务层信号,不是 HTTP 层真实状态 - 真正可靠的状态码,只能从包装后的 ResponseWriter 的
WriteHeader调用中捕获
如何把耗时安全写进日志且不拖慢请求
Revel 默认用 revel.INFO 级别往 stdout 写日志,但高频请求下 fmt.Printf 或拼接字符串会触发大量内存分配;更糟的是,如果日志输出绑定到慢速终端或文件,整个 goroutine 会被阻塞。
推荐做法是复用 Revel 自带的 logger 实例,但避免在 filter 中做字符串拼接:
- 用
revel.TRACE或自定义 logger(如revel.Config.StringDefault("log.level", "info")控制开关) - 日志内容固定字段:method、path、status(需包装 ResponseWriter 后获取)、duration_ms、traceId(可用
c.Params.Route.Name或生成短 ID) - 不要在 filter 中调用
c.RenderJson()或读取c.Params.Get("body")—— 这些操作本身就有开销,会污染耗时统计 - 若需区分慢请求,加阈值判断:
if duration > 500*time.Millisecond再打revel.WARN,避免日志爆炸
Revel 中间件注册顺序对耗时统计的影响
Revel 的 Filters 切片是硬编码顺序(见 revel/filter.go),你自定义的 TimingFilter 插在哪,就决定了它测的是哪一段耗时。比如:
- 插在
PanicFilter后、RouterFilter前 → 测的是「从请求接入到路由匹配前」,不含 panic 恢复开销 - 插在
ActionInvoker后 → 根本不会执行,因为它是最后一个 - 最合理位置是插在
ParamsFilter后、SessionFilter前:覆盖参数解析、会话恢复、认证、授权、Action 执行、模板渲染全过程
注意:Revel 的 filter 执行是单向链式,没有「响应阶段」回调机制,所以 TimingFilter 必须是环绕型(即自己控制调用下游并收尾),不能只写「请求前」逻辑。


















