记一次生产环境死锁问题分析

一、问题背景

最近在做的项目中生产环境频繁出现数据库死锁的问题,解决一个,又来一个,最后数据库不死锁了,多了个请求文件服务器永久阻塞的问题,也是折腾了许久才解决掉。

二、定位死锁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​​的报错

记一次生产环境死锁问题分析_mysql

定位

接下来我们就去定位一下相关 SQL,(数据库版本是 8.0.2)

SELECT * FROM information_schema.INNODB_TRX;

INNODB_TRX 表提供了当前在 InnoDB 内部执行的所有事务信息,包含事务是否在等待锁,事务何时开始以及事务正在执行的SQL语句(如果有的话,sql语句阻塞就可以显示)。

可以看到后面的 update 语句处于 ​​LOCK WAIT​​ 状态,在 trx_query 字段可以看到后面执行的 SQL。

记一次生产环境死锁问题分析_sql_02

然后呐,我们想找造成锁等待的源头 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 信息。

记一次生产环境死锁问题分析_死锁_03

通过 ​​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​

记一次生产环境死锁问题分析_死锁_04

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​​ 问题解决!