记一次生产环境死锁问题分析
一、问题背景
最近在做的项目中生产环境频繁出现数据库死锁的问题,解决一个,又来一个,最后数据库不死锁了,多了个请求文件服务器永久阻塞的问题,也是折腾了许久才解决掉。
二、定位死锁SQL
由于线上的问题已经处理掉了,只能稍微模拟一下定位的步骤。
复现
首先,我们打开一个 SQL 窗口,关闭 MySQL 数据库的自动提交,然后去修改一条数据。
set autocommit = 0; -- 关闭数据库自动提交
update fs_pdf_transfer set progress = 99 where pdf_transfer_id = 2441 -- 执行完后事务并没有结束,需手动 commit
然后打开一个新窗口,去修改同一条记录
update fs_pdf_transfer set progress = 98 where pdf_transfer_id = 2441
你会发现这个语句运行一会后就出现Lock wait
的报错
定位
接下来我们就去定位一下相关 SQL,(数据库版本是 8.0.2)
SELECT * FROM information_schema.INNODB_TRX;
INNODB_TRX 表提供了当前在 InnoDB 内部执行的所有事务信息,包含事务是否在等待锁,事务何时开始以及事务正在执行的SQL语句(如果有的话,sql语句阻塞就可以显示)。
可以看到后面的 update 语句处于 LOCK WAIT
状态,在 trx_query 字段可以看到后面执行的 SQL。
然后呐,我们想找造成锁等待的源头 SQL,这里肯定就是 trx_state 是 RUNNING
状态的记录了,表示这个事务一直是 RUNNING
状态,没有提交,也没有回滚。但是这条记录的 trx_query 里面是空的,其实这里为空的意思就是事务未提交也未回滚。
此时可以将该条记录的 trx_mysql_thread_id
,就是 13896 放在以下 SQL 中,然后执行。
select * from performance_schema.events_statements_current where THREAD_ID in (select THREAD_ID from performance_schema.threads where PROCESSLIST_ID=13829)
看到 SQL_TEXT
字段,还不是我们要查的 SQL 信息。
通过 performance_schema.events_statements_history
表,查看数据库最近执行的一些 sql 语句,同样是将 trx_mysql_thread_id
放进去
SELECT EVENT_ID,CURRENT_SCHEMA, SQL_TEXT FROM performance_schema.events_statements_history WHERE THREAD_ID in (SELECT THREAD_ID FROM performance_schema.threads WHERE PROCESSLIST_ID=13829) order by event_id
可以看到之前执行的 update fs_pdf_transfer set progress = 99 where pdf_transfer_id = 2441
show engine innodb status
show engine innodb status
是 MySQL
提供的一个用于查看 innodb
引擎时间信息的工具,就目前来说有两处比较常用的地方一、死锁分析 二、innodb
内存使用情况。
执行这个之前,测试环境我们可以先设置下 set GLOBAL innodb_status_output_locks=ON;
这样输出的信息更详细。
---TRANSACTION 3861095, ACTIVE 1204 sec
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 13829, OS thread handle 140147875874560, query id 2483260 192.168.18.214 root
TABLE LOCK table `erow_biz`.`fs_pdf_transfer` trx id 3861095 lock mode IX
RECORD LOCKS space id 2351 page no 6 n bits 112 index PRIMARY of table `erow_biz`.`fs_pdf_transfer` trx id 3861095 lock_mode X locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 33; compact format; info bits 128
可以看到第二个 update 语句锁等待的详细信息,这里显示有两个锁,一个意向排他锁IX(表级锁),一个记录上的行锁(X)
三、线上问题
通过上面的步骤,我们大致能够定位到出现问题的SQL。
先delete再insert
此次线上问题,我最终定位到的是一条删除 SQL,然后找到对应的 Java
代码,分析这块代码发现,是在同一个事务里先执行了删除操作,然后再执行了插入操作,参数相同,类似这样:
delete from fs_file where file_id = 111;
insert into fs_file(file_id) values(111);
网上一顿查,最后找到了这位大佬的文章分析:MySQL死锁案例分:先delete,再insert,导致死锁
最后的解决办法就是在删除前先查询,如果有再删除。
此时,此处的死锁问题就解决掉了。
但是后面出现了新的死锁。
先insert再update
新的死锁问题定位到的代码,是在同一个事务里先执行insert
操作,接着执行 update
操作。主键是自增的。
这个通过 show engine innodb status
看到如下信息:
*** (1) TRANSACTION:
TRANSACTION 4949999, ACTIVE 1 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 107 lock struct(s), heap size 24696, 5998 row lock(s), undo log entries 3
MySQL thread id 97584, OS thread handle 140126962161408, query id 12685049 192.168.1.224 root updating
update
ytb_package_file
set pdf_transfer_id = 5673, transfer_status = 'TRANSFER_DOING'
where source_file_guid = '83f87744-210c-4b87-be3a-ea7fc066dc4f'
and template_detail_id = 0
*** (1) HOLDS THE LOCK(S): -- 持有锁
RECORD LOCKS space id 3171 page no 5 n bits 144 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949999 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
0: len 8; hex 73757072656d756d; asc supremum;;
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3171 page no 337 n bits 136 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949999 lock_mode X waiting -- 等待锁(136)
*** (2) TRANSACTION:
TRANSACTION 4949998, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 3
MySQL thread id 97582, OS thread handle 140126975891200, query id 12685057 192.168.1.224 root updating
update
ytb_package_file
set pdf_transfer_id = 5674, transfer_status = 'TRANSFER_DOING'
where source_file_guid = 'c4580bde-38c5-43dd-9342-4988c17541e2'
and template_detail_id = 0
*** (2) HOLDS THE LOCK(S): -- -- 持有锁
RECORD LOCKS space id 3171 page no 337 n bits 136 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949998 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3171 page no 5 n bits 144 index PRIMARY of table `erow_biz`.`ytb_package_file` trx id 4949998 lock_mode X waiting -- 等待锁(144)
*** WE ROLL BACK TRANSACTION (2)
两个事务同时持有对方需要的锁,这个问题的具体原因还是因为我太菜了,没分析出来,后面有了进展再补上吧。
代码的话,将 insert 和 update 放不同的事务就解决掉这个死锁问题了。
请求永久阻塞
在处理完上面的死锁问题后,生产环境还是经常卡死,怀疑还有其他地方有死锁问题,但是根本找不到,奇怪的是测试环境一切正常,就是生产环境经常卡死,最后通过日志分析,发现老是卡在使用 Feign
调用文件服务的一个地方,文件服务一切正常,业务服务发送请求上传文件,请求都没发出去就一直阻塞在这,百思不得其解。
后面通过 jstack
命令分析,发现如下信息。
"com.alibaba.nacos.client.Worker.longPolling.fixed-192.168.1.225_8848" #73 daemon prio=5 os_prio=0 tid=0x00007f4d48005000 nid=0xdad runnable [0x00007f4e2f8fb000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
- locked <0x000000071eba9618> (a java.io.BufferedInputStream)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735)
好像是和 HttpClient
有关系,一顿搜索终于发现端倪:竟然是 jdk 的一个 bug,详情请看这篇分析: Java HttpClient execute 永久阻塞问题
恰巧生产环境的 JDK 版本不在这个 bug 的修复范围内。
奇怪为啥测试环境没有这个问题,然后我去看了下测试环境 OpenFeign
的配置:
feign:
sentinel:
enabled: true
okhttp:
enabled: true
httpclient:
enabled: false
好吧,破案了,测试环境服务间调用使用的是 okhttp
,正式环境是 httpclient
,遂改成 okhttp
问题解决!