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

一、问题背景

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

二、定位死锁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 问题解决！

MySql各种锁机制的学习

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