事务耗时需从db.Transaction回调最外层测量,涵盖Begin、CRUD、锁等待、Commit/Rollback全过程;仅测SQL执行或依赖GORM日志会遗漏关键延迟,高并发下锁竞争耗时可能占大头。

事务执行时间不等于SQL耗时,得从db.Transaction入口开始测
db.Transaction本身不记录耗时,它只是个包装器;真正执行时间包含事务开启、所有CRUD、锁等待、Commit/rollback全过程。如果你只在tx.Create()前后打点,会漏掉Begin和提交阶段的延迟,尤其在高并发下锁竞争明显时,这部分可能占大头。
- 必须在
db.Transaction回调函数最外层加计时,比如用time.Now()和time.Since() - 别依赖GORM日志里的
duration字段——它只统计单条SQL执行时间,不含事务上下文开销 - 若启用了
PrepareStmt: true,首次事务可能多一次预编译耗时,后续才稳定,压测时注意预热
如何把事务耗时打到日志或监控系统里
推荐在事务函数体内注册tx.AfterCommit()和tx.AfterRollback()钩子,把耗时和结果一起上报。注意这两个钩子只对当前tx实例生效,传错对象(比如传了原始db)就收不到。
-
tx.AfterCommit()里可调用Prometheus的histogram.Observe()记录成功耗时 -
tx.AfterRollback()里同样打点,但标注result="failed",方便区分失败是否因超时引发 - 避免在钩子里做阻塞操作(如HTTP调用),否则会拖慢事务提交——用异步goroutine或消息队列解耦
为什么pprof抓不到长事务?因为事务本身不占CPU
pprof profile的是CPU或内存分配,而慢事务往往卡在IO等待(如行锁争用、磁盘刷盘、网络延迟),这些在线程栈里表现为select或syscall.Syscall,不是热点函数。你看到runtime.gopark一堆,不代表代码写得差,可能是MySQL那边在等锁。
- 查慢事务优先看MySQL的
information_schema.INNODB_TRX表,过滤trx_started早于当前时间10秒的记录 - 配合
SHOW ENGINE INNODB STATUS看锁等待链,确认是不是tx.Clauses(clause.Locking{Strength: clause.LockingStrengthUpdate})被其他事务堵住了 - GORM没提供事务级trace ID注入点,如需全链路追踪,得手动把
ctx传进db.WithContext(ctx),并在事务开始时写入span
事务超时控制不能只靠context.WithTimeout
context超时只能中断Go协程,但MySQL服务端的事务不会自动回滚——它还在运行,连接可能卡在sleep状态,慢慢吃光连接池。
- 必须配MySQL的
innodb_lock_wait_timeout(默认50秒)和wait_timeout(默认8小时),前者管锁等待,后者管空闲连接 - 在
db.Transaction里用context.WithTimeout是必要的,但得配套加defer tx.Rollback()兜底,防止panic后连接泄露 - 别信
db.Exec("SET SESSION innodb_lock_wait_timeout = 5")这种写法——GORM连接池会复用连接,这个设置可能污染其他请求
事务耗时监控真正的难点不在打点,而在区分「是应用逻辑慢」还是「数据库侧卡住」。一个事务跑了3秒,你得立刻知道这3秒里MySQL花了多少、锁等了多久、Go侧调度停顿几次——这些信息分散在不同系统里,没有银弹能自动串起来。











