最简方案是函数开头写 start := time.Now(),defer 中用闭包调用 time.Since(start);它轻量无侵入、覆盖所有返回路径,但须避免在 defer 内直接调 time.Now() 导致捕获错误时间点。

用 defer + time.Now() 统计函数耗时最简方案
直接在函数开头写 defer 调用一个闭包,捕获进入时刻,退出时算差值——这是 Go 里最轻量、最无侵入的耗时统计方式。它不依赖外部库,不改调用逻辑,也不需要手动配对 Start/End。
常见错误是把 time.Now() 放在 defer 语句里直接调用,结果记录的是 defer 执行时刻(即函数返回时),而非函数开始时刻。必须提前求值。
- 正确写法:
start := time.Now(); defer func() { log.Printf("cost: %v", time.Since(start)) }() - 错误写法:
defer func() { log.Printf("cost: %v", time.Since(time.Now())) }()(time.Now()在 defer 实际执行时才调,永远接近 0) - 如果函数有多个
return,defer仍只执行一次,且总在最后,天然覆盖所有出口
带上下文和标签的耗时日志怎么加?
纯打时间不够,线上排查常需知道「谁调的」「参数是什么」「是否出错」。这时别拼字符串,用结构化字段更利于日志采集和检索。
推荐用 log/slog(Go 1.21+)或 zap 等结构化 logger,把函数名、关键参数、返回状态作为字段传入,而不是塞进消息体。
- 避免:
log.Printf("HandleUser(id=%d) cost %v", id, time.Since(start)) - 推荐:
slog.With("fn", "HandleUser").With("user_id", id).Info("exit", "cost", time.Since(start), "err", err) - 注意:不要把敏感字段(如密码、token)直接打日志;
err值可判空再传,避免slog.Any("err", nil)导致 panic
为什么不用 runtime.Caller 自动获取函数名?
有人想自动提取当前函数名来省掉手写字符串,但 runtime.Caller 开销不小(要解析栈帧),在高频函数里会明显拖慢性能,且结果不可靠(内联、编译优化可能让 Caller 返回不一致的文件行号或名字)。
使用 uber-go/dig 在 Golang 中实现依赖注入——基于反射容器,提供 Provide/Invoke、dig.In/dig.Out 参数与结果对象,支持命名依赖等
真正需要自动标注的场景,更适合用 trace SDK(如 otel/trace),它通过编译器插桩或框架集成做无感埋点,不是靠运行时查栈。
-
runtime.Caller(1)在压测中可能使 P99 耗时上升 5%~10% - 交叉编译或开启
-gcflags="-l"(禁用内联)时,Caller 返回的函数名可能变成main.main.func1这类匿名名 - 若真要自动化,优先考虑构建期代码生成(如 go:generate + ast 解析),而非运行时反射
并发 goroutine 里用 defer 统计耗时要注意什么?
在 go func() { ... }() 里用 defer 统计,逻辑上没问题,但容易忽略两个现实问题:goroutine 生命周期不可控、日志输出竞争。
比如大量短生命周期 goroutine 同时打日志,可能冲垮日志系统;或者 goroutine 已结束但主流程已退出,日志来不及 flush。
- 务必确保 logger 是线程安全的(
slog默认是,log.Printf也是) - 避免在 defer 里做重操作(如写文件、发 HTTP),只记日志或发指标;耗时统计本身应控制在微秒级
- 如果 goroutine 可能被
context.WithTimeout中断,耗时应以实际执行时长为准,不是从启动到被 cancel 的总时长
真正难的不是写那三行 defer,而是决定在哪一级函数埋点——太深(如 DAO 层每个 SQL)会噪音大,太浅(只在 HTTP handler)又看不到瓶颈。通常建议先在 handler 和关键业务入口层加,跑起来再根据 pprof 和日志热区下钻。
golang免费学习笔记(深入):立即使用
在学习笔记中,你将探索golang的核心概念和高级技巧!










