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

现象

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_waits\G

查看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;} } '