应用系统时不时的有锁发生分析

2023年 8月 15日 59.2k 0

现象

Lock wait timeout exceeded; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction

自动提交

mysql> show variables like '%commit%';
+-----------------------------------------+-------------------+
| Variable_name | Value |
+-----------------------------------------+-------------------+
| autocommit | ON |

关键是找头锁,阻塞源头。否则开发总是问你为shong么。谁阻塞了谁,怎么就阻塞了。

收集到的信息

方法一:(是的,还有方法2和方法3)

结论:通过blocking_pid 找源头,一般blocking_pid为空的就是没有被阻塞的,没有被阻塞的就是源头喽。

select * from sys.innodb_lock_waitsG

查看blocking在做啥

select * from information_schema.processlist where id in (select blocking_pid from sys.innodb_lock_waits )G

*************************** 1. row ***************************

 ID: 4208595

USER: hcbm

HOST: 10.206.160.52:40182

DB: hcbm_contract

COMMAND: Sleep

TIME: 132

STATE:

INFO: NULL

竟然是Sleep,睡着了?为什么睡着了还能阻塞别人?活动时间是132秒了,且time在持续增加。只是info空了,说明SQL已经执行完成了。我的慢日志是3秒,在慢日志中没有看到慢SQL,那么肯定SQL执行不慢。那就是没有提交了,至于为什么没有提交只能找开发了。

可能会问为什么他就不是被阻塞造成的无法提交呢?总结呗,遇到百八十次lock wait timeout再配合做实验就知道了,被阻塞的state状态如下,是updating的。delete执行了11秒,状态updating,并且他的语句是会被显示出来的。

方法2的结论:通过对所有有锁的事务按照time时间排序,一般执行时间最长的就是头锁喽,只要kill他基本就能解决问题(是否可以kill找开发)。但是有的时候头锁不只是一个。(SQL内容自己想)

方法3的结论:查看未提交的事务进行排序。总之都是要排序(SQL内容自己想)

下面开始找证据,通过脚本解析binlog

sh /tmp/summarize_binlogs.sh >> /tmp/summarize_binlogs.log  这个时间是我们通过sys.innodb_lock_waits查询出来的时间

找出事务大于200秒的$19>200

cat /tmp/summarize_binlogs.log|grep Transaction|awk '{if($19>200)print}'

不好意思,找出来的大事务就没有截图了(cat出来的结果mysqldba都知道啥意思),然后再通过解析全量的binlog来对应找到完整的事务,从begin到commit,拿给开发甩他脸上。

这个大事务怎么和上面的锁结合起来?

cat出来的大事务也就有几个,这几个xid从全量解析的binlog中搜索,对比下thread_id,并且binglog里有时间#220809 15:34:00,通过执行SQL的时间以及 sys.innodb_lock_waits查询出的waiting_trx_started时间进行对比,或者information_schema.processlist收集到的信息,我当时看到这个是一致的,并且时间在15点30到15点40之间。这个长事务就是上面Sleep线程执行的SQL。这个SQL抓出来后很简单就是一个update,手动执行很快。应该是开发在哪里事务套了事务

下面是脚本summarize_binlogs.sh。此脚本来自运维内参

特别鸣谢范博施

注意:脚本执行较慢,时间越精确越好,10分钟以内,也可能是我的服务器不好。

cat summarize_binlogs.sh
#!/bin/bash
BINLOG_FILE="master-bin.000196"
START_TIME="2022-08-09 15:00:10"
STOP_TIME="2022-08-09 16:00:00"
mysqlbinlog --base64-output=decode-rows -vv --start-datetime="${START_TIME}"  --stop-datetime="${STOP_TIME}" ${BINLOG_FILE} | awk
'BEGIN {xid="null";s_type=""; stm="";endtm="";intsta=0;inttal=0;s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;bf=0;period=0;}
{
if (match($0,/^(BEGIN)/)) {bg=1;}
if (match($0,/#.*server id/)) {if(bg==1){statm=substr($1,2,6)" "$2;cmd=sprintf("date -d "%s" +%%s", statm);cmd|getline intsta;close(cmd);bg=0;bf=1;}else if(bf==1){endtm=substr($1,2,6)" "$2;cmd=sprintf("date -d "%s" +%%s", endtm);cmd|getline inttal;close(cmd);}}
if(match($0, /#.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1}
else if (match($0, /#.*Xid =.*/)) {xid=$(NF)}
else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;}  
else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;}
else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;}  
else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; }  
else if (match($0, /^(COMMIT)/)) {period=inttal-intsta;if(inttal==0){period=0};print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : "
delete_count " Xid : "xid" period : "period" ] n+----------------------+----------------------+----------------------+----------------------+";
count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0;bf=0;bg=0;} } '

相关文章

Oracle如何使用授予和撤销权限的语法和示例
Awesome Project: 探索 MatrixOrigin 云原生分布式数据库
下载丨66页PDF,云和恩墨技术通讯(2024年7月刊)
社区版oceanbase安装
Oracle 导出CSV工具-sqluldr2
ETL数据集成丨快速将MySQL数据迁移至Doris数据库

发布评论