專案場景：一次線上MySQL死鎖告警原因排查
最近處理了一次線上資料告警，記錄一下，
問題描述
同步書架書籍的介面頻繁拋出例外，提示資料庫出現死鎖，例外如下：
本日例外次數：2，例外日志：java.lang.RuntimeException: org.springframework.dao.DeadlockLoserDataAccessException:
### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction ### The error may involve com.iflytek.hmreader.order.dao.UBookShelfMapper.batchInsertOrUpdate-Inline
### The error occurred while setting parameters
### SQL: insert into `um_user_bookshelf` (`app_id`, `channel_id`, `version_id`, `user_id`, `book_id`, `chapter_id`, `progress`,`listened`, `from_user_id`, `create_time`,`update_time`,`sync_time`) values (?,?,?,?,?,?,?,?,?,NOW(),?,?) , (?,?,?,?,?,?,?,?,?,NOW(),?,?) , (?,?,?,?,?,?,?,?,?,NOW(),?,?) , (?,?,?,?,?,?,?,?,?,NOW(),?,?) on duplicate key update chapter_id = values(chapter_id), progress = values(progress),listened = values(listened),update_time = values(update_time)
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction ; SQL []; Deadlock found when trying to get lock; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
org.springframework.dao.DeadlockLoserDataAccessException:
### Error updating database. Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction ### The error may involve com.iflytek.hmreader.order.dao.UBookShelfMapper.batchInsertOrUpdate-Inline
### The error occurred while setting parameters
### SQL: insert into `um_user_bookshelf` (`app_id`, `channel_id`, `version_id`, `user_id`, `book_id`, `chapter_id`, `progress`,`listened`, `from_user_id`, `create_time`,`update_time`,`sync_time`) values (?,?,?,?,?,?,?,?,?,NOW(),?,?) , (?,?,?,?,?,?,?,?,?,NOW(),?,?) , (?,?,?,?,?,?,?,?,?,NOW(),?,?) , (?,?,?,?,?,?,?,?,?,NOW(),?,?) on duplicate key update chapter_id = values(chapter_id), progress = values(progress),listened = values(listened),update_time = values(update_time)
### Cause: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction ; SQL []; Deadlock found when trying to get lock; try restarting transaction; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:263)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:75)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:447)
at com.sun.proxy.$Proxy70.insert(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.insert(SqlSessionTemplate.java:279)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:56)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
at com.sun.proxy.$Proxy115.batchInsertOrUpdate(Unknown Source)
at com.iflytek.hmreader.order.service.UmBookShelfServiceImpl.updBookShelf(UmBookShelfServiceImpl.java:134)
at com.alibaba.dubbo.common.bytecode.Wrapper10.invokeMethod(Wrapper10.java)
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:70)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:132)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:113)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.Util.getInstance(Util.java:408)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:952)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3976)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3912)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2530)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2683)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:498)
at io.shardingsphere.shardingjdbc.executor.PreparedStatementExecutor$4.executeSQL(PreparedStatementExecutor.java:158)
at io.shardingsphere.shardingjdbc.executor.PreparedStatementExecutor$4.executeSQL(PreparedStatementExecutor.java:154)
at io.shardingsphere.core.executor.sql.execute.SQLExecuteCallback.execute0(SQLExecuteCallback.java:85)
at io.shardingsphere.core.executor.sql.execute.SQLExecuteCallback.execute(SQLExecuteCallback.java:69)
at io.shardingsphere.core.executor.ShardingExecuteEngine.syncGroupExecute(ShardingExecuteEngine.java:182)
at io.shardingsphere.core.executor.ShardingExecuteEngine.groupExecute(ShardingExecuteEngine.java:158)
at io.shardingsphere.core.executor.sql.execute.SQLExecuteTemplate.executeGroup(SQLExecuteTemplate.java:71)
at io.shardingsphere.core.executor.sql.execute.SQLExecuteTemplate.executeGroup(SQLExecuteTemplate.java:54)
at io.shardingsphere.shardingjdbc.executor.AbstractStatementExecutor.executeCallback(AbstractStatementExecutor.java:122)
at io.shardingsphere.shardingjdbc.executor.PreparedStatementExecutor.execute(PreparedStatementExecutor.java:161)
at io.shardingsphere.shardingjdbc.jdbc.core.statement.ShardingPreparedStatement.execute(ShardingPreparedStatement.java:139)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:46)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:74)
at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50)
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117)
at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76)
at sun.reflect.GeneratedMethodAccessor210.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:63)
at com.sun.proxy.$Proxy116.update(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:198)
at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:185)
at sun.reflect.GeneratedMethodAccessor209.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:434)
... 34 more
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:108)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:70)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:132)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:113)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
原因分析：
提示：這里填寫問題的分析：
我們采用的是5.7.17版本的mysql資料庫，事務隔離級別是默認的RR（Repeatable-Read），采用innodb引擎，其中涉及的表為
CREATE TABLE um_user_bookshelf_62 (
id bigint(20) NOT NULL AUTO_INCREMENT COMMENT '主鍵',
app_id varchar(50) NOT NULL DEFAULT '43' COMMENT '產品ID',
channel_id varchar(50) NOT NULL DEFAULT '0' COMMENT '渠道ID',
version_id bigint(20) NOT NULL DEFAULT '0' COMMENT '版本ID',
user_id varchar(32) DEFAULT NULL,
book_id bigint(20) NOT NULL COMMENT '書籍ID',
chapter_id bigint(20) DEFAULT NULL COMMENT ' 章節編號',
progress varchar(50) DEFAULT NULL COMMENT '（閱讀/聽書）進度',
listened int(1) DEFAULT NULL COMMENT '上次是否是聽書標志（1：看書、2：真人、3：TTS）',
from_user_id varchar(32) DEFAULT NULL COMMENT '書架資產轉移賬戶ID',
create_time datetime NOT NULL COMMENT '創建時間',
update_time datetime NOT NULL COMMENT '用戶在客戶端最后閱讀記錄時間',
sync_time datetime NOT NULL DEFAULT '1970-01-01 00:00:00' COMMENT '用戶最后獲取更新書籍記錄時間',
PRIMARY KEY (id),
UNIQUE KEY um_shelf_index_user_id_book_id (user_id,book_id) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=653275640704925698 DEFAULT CHARSET=utf8 COMMENT='用戶書架圖書記錄表';
表結構并不復雜，除去主鍵索引外還有一個唯一索引，那么現在就去看一下MySQL的日志，看一下在執行這個操作前后資料在執行什么操作，這里可以通過SHOW ENGINE INNODB STATUS來查看最近捕獲到的死鎖日志
=====================================
2022-04-01 10:41:02 0x7f051c0c6700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 2 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1658263 srv_active, 0 srv_shutdown, 46119058 srv_idle
srv_master_thread log flush and writes: 47773811
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1874466
OS WAIT ARRAY INFO: signal count 1843076
RW-shared spins 0, rounds 3405123, OS waits 1707831
RW-excl spins 0, rounds 197500, OS waits 3749
RW-sx spins 1429, rounds 40856, OS waits 1194
Spin rounds per wait: 3405123.00 RW-shared, 197500.00 RW-excl, 28.59 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2022-03-31 22:10:24 0x7f051c108700
*** (1) TRANSACTION:
TRANSACTION 949308891, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 34888817, OS thread handle 139658880173824, query id 31638369 172.22.149.74 ydorder update
insert into `um_user_bookshelf_32` (`app_id`, `channel_id`, `version_id`, `user_id`, `book_id`, `chapter_id`, `progress`,`listened`, `from_user_id`, `create_time`,`update_time`,`sync_time`, id) values ('43','201002',395,'302107202231477720',622312,2,'0',1,null,NOW(),'2021-10-23 23:18:22','1970-01-01 00:00:00', 716413229296390144), ('43','201002',395,'302107202231477720',631104,3,'195',1,null,NOW(),'2022-03-31 22:10:18','1970-01-01 00:00:00', 716413229296390145), ('43','201002',395,'302107202231477720',621438,0,'0',1,null,NOW(),'2021-10-23 23:22:19','1970-01-01 00:00:00', 716413229296390146), ('43','201002',395,'302107202231477720',675781,0,'0',1,null,NOW(),'2021-10-23 23:22:39','1970-01-01 00:00:00', 716413229296390147), ('43','201002',395,'302107202231477720',678183,0,'0',1,null,NOW(),'2021-10-23 23:23:06','1970-01-01 00:00:00', 716413229296390148), ('43','201002',395,'302107202231477720',678455,0,
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 5436 page no 63 n bits 464 index um_shelf_index_user_id_book_id of table `sharding_3`.`um_user_bookshelf_32` trx id 949308891 lock_mode X waiting
Record lock, heap no 150 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 18; hex 333032313037323032323331343737373230; asc 302107202231477720;;
1: len 8; hex 8000000000097ee8; asc ~ ;;
2: len 8; hex 88ab8aab239a1004; asc # ;;
*** (2) TRANSACTION:
TRANSACTION 949308890, ACTIVE 0 sec inserting, thread declared inside InnoDB 4994
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 5 row lock(s), undo log entries 3
MySQL thread id 34888816, OS thread handle 139659922409216, query id 31638370 172.22.149.73 ydorder update
insert into `um_user_bookshelf_32` (`app_id`, `channel_id`, `version_id`, `user_id`, `book_id`, `chapter_id`, `progress`,`listened`, `from_user_id`, `create_time`,`update_time`,`sync_time`, id) values ('43','201002',395,'302107202231477720',622312,2,'0',1,null,NOW(),'2021-10-23 23:18:22','1970-01-01 00:00:00', 716413229304774656), ('43','201002',395,'302107202231477720',631104,4,'0',1,null,NOW(),'2022-03-31 22:10:20','1970-01-01 00:00:00', 716413229304774657), ('43','201002',395,'302107202231477720',621438,0,'0',1,null,NOW(),'2021-10-23 23:22:19','1970-01-01 00:00:00', 716413229304774658), ('43','201002',395,'302107202231477720',675781,0,'0',1,null,NOW(),'2021-10-23 23:22:39','1970-01-01 00:00:00', 716413229304774659), ('43','201002',395,'302107202231477720',678183,0,'0',1,null,NOW(),'2021-10-23 23:23:06','1970-01-01 00:00:00', 716413229304774660), ('43','201002',395,'302107202231477720',678455,0,'0
*** (2) HOLDS THE LOCK(S): 事務2持有的鎖
RECORD LOCKS space id 5436 page no 63 n bits 464 index um_shelf_index_user_id_book_id of table `sharding_3`.`um_user_bookshelf_32` trx id 949308890 lock_mode X
Record lock, heap no 150 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 18; hex 333032313037323032323331343737373230; asc 302107202231477720;;
1: len 8; hex 8000000000097ee8; asc ~ ;;
2: len 8; hex 88ab8aab239a1004; asc # ;;
Record lock, heap no 154 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 18; hex 333032313037323032323331343737373230; asc 302107202231477720;;
1: len 8; hex 800000000009a140; asc @;;
2: len 8; hex 88ab8aab239a100a; asc # ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 5436 page no 63 n bits 464 index um_shelf_index_user_id_book_id of table `sharding_3`.`um_user_bookshelf_32` trx id 949308890 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 150 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 18; hex 333032313037323032323331343737373230; asc 302107202231477720;;
1: len 8; hex 8000000000097ee8; asc ~ ;;
2: len 8; hex 88ab8aab239a1004; asc # ;;
*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 949318674
Purge done for trx's n:o < 949318646 undo n:o < 0 state: running but idle
History list length 19
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421145291578096, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
死鎖日志的結構很清晰，主要分為兩部分 ，*** (1) TRANSACTION和*** (2) TRANSACTION,其中事務1正在執行insert操作，該操作正在申請索引um_shelf_index_user_id_book_id的X鎖(排它鎖)，所以會提示lock_mode X waiting，再看事務2的部分，它持有了S鎖，并在申請lock_mode X locks gap，這里由于是添加的是唯一索引，申請同一個X鎖造成了回圈等待，最后由于事務1的權重比較小，被選擇了回滾，
從日志里面可以看出 這是個批量插入操作，兩個事物操作的資料是一樣，由于添加了userId+bookId的唯一索引，兩個事物之間會出現互相申請鎖的情況，陷入等待回圈，造成了死鎖，到這里可以推斷是由于并發請求導致的，然后我去翻看了一下nginx網關的訪問日志，發現確實是這樣，同一時間 端發起了多次重復請求，如下圖所示：
解決方案：
端呼叫的代碼需要排查，同時介面需要做冪等性處理，
轉載請註明出處，本文鏈接：https://www.uj5u.com/shujuku/454676.html
標籤：MySQL
上一篇：CentOS7 安裝MySQL5.7企業版（商業版）及修改my.cnf默認datadir、socket路徑后無法啟動的處理方法