日常运维中,innodb_trx视图中经常会出现running时间很长的事务,但是并没有显示sql语句,很多DBA对这类问题很困惑。
比如上图中,show processlist 查看到ID对应的session一直存在,status状态时而running时而 sleep,最后分析发现,应用程序使用 begin、start transction 启动了一个大事务,不停的轮询更新数据,大事务运行时间超过 1 天。
如何追踪定位?
一般情况下,应用程序通过begin执行显示事务后,事务中的sql已经执行,但是该显示事务一直没有提交时就会出现这种现象。下面sql语句会查询到“空事务”中执行的上一条sql语句,拿到sql后找开发一起排查sql来源,最后尝试复现找到根因。
select trx_id,trx_operation_state,trx_mysql_thread_id prs_id,now(),
trx_started,to_seconds(now())-to_seconds(trx_started) trx_es_time,
user,db,host,command,state,Time,info current_sql,PROCESSLIST_INFO
last_sql,t4.ROWS_AFFECTED 'ROWS_AFFECTED(last)',t4.ROWS_SENT as 'ROWS_SENT(last)'
,t4.ROWS_EXAMINED as 'ROWS_EXAMINED(last)',t1.trx_rows_locked,t1.trx_rows_modified
from information_schema.innodb_trx t1,information_schema.processlist t2,performance_schema.threads
t3,performance_schema.events_statements_current t4 where t1.trx_mysql_thread_id=t2.id and
t1.trx_mysql_thread_id=t3.PROCESSLIST_ID and t1.trx_mysql_thread_id!=connection_id() and
t3.THREAD_ID = t4.THREAD_ID and to_seconds(now())-to_seconds(trx_started) >= 5;
看一个案例
下面案例就是“空事务”引发的锁阻塞。
#############正在锁的事务#############
mysql>SELECT lock_id,lock_trx_id,lock_mode,lock_table,lock_index,lock_data FROM INFORMATION_SCHEMA.INNODB_LOCKS;
lock_id lock_trx_id lock_mode lock_table lock_index lock_data
517490031:70:548240:33 517490031 X `campaign_prod`.`reward_campaign_instance` PRIMARY 64404684
517487888:70:548240:33 517487888 X `campaign_prod`.`reward_campaign_instance` PRIMARY 64404684
#############锁等待##################
mysql>SELECT * FROM information_schema.innodb_lock_waits;
requesting_trx_id requested_lock_id blocking_trx_id blocking_lock_id
517490031 517490031:70:548240:33 517487888 517487888:70:548240:33
#############运行中的事务#############
mysql>SELECT trx_id,trx_state,trx_started,trx_mysql_thread_id,trx_query,trx_operation_state FROM information_schema.INNODB_TRX;
trx_id trx_state trx_started trx_mysql_thread_id trx_query trx_operation_state
517490355 RUNNING 2023-11-24 16:19:12 63065298 NULL NULL
517490031 LOCK WAIT 2023-11-24 16:19:03 63022117 UPDATE reward_campaign_instance SET OBJECT_VERSION_NUMBER = OBJECT_VERSION_NUMBER+1,last_updated_by = 'admin',last_updated_by_name = 'admin',last_update_date = '2023-11-24 16:19:03.162000',last_accrual_date = '2023-11-24 16:19:03.160000',accrual_amount_total = 3937.700 WHERE id = 64404684 AND OBJECT_VERSION_NUMBER = 3 starting index read
517489792 RUNNING 2023-11-24 16:18:44 63065302 NULL NULL
517487888 RUNNING 2023-11-24 16:16:38 63065211 NULL NULL
分析
- 通过innodb_lock_waits看到,517490031被517487888堵塞
- 通过innodb_locks看到,517490031 和517487888 都想要修改主键为64404684的行记录
- 查看innodb_trx,517490031被堵塞,状态为lock wait,能看到是一个单表更新
- 查看innodb_trx,517487888是一个 RUNNING 的显示事务,应该是没有提交,才导致后面的事务被堵。
517487888应该为delete或者update语句,在操作主键为64404684的行记录时,加了X锁,但是由于“显示事务”没有提交,导致后面的517490031事务的update等待X锁。
“空事务”可能出现的原因
1> 正常业务逻辑中显示事务,本身执行时间很长,导致影响的行比较多;
2> 服务异常导致显示事务未提交,比如业务逻辑中需要用到activemq,但由于集群故障导致发送mq消息阻塞,导致mysql事务执行超时。
3> 第三方接口响应超时,导致事务运行时间过长,表面看起来就是innodb_trx下出现很多空事务;