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

1,312 阅读6分钟

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

一、问题背景

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

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

image-20220821204837052

定位

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

 SELECT * FROM information_schema.INNODB_TRX;

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

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

image-20220821213548569

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

image-20220821214321438

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

image-20220821214801885

show engine innodb status

show engine innodb statusMySQL 提供的一个用于查看 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各种锁机制的学习