Today we execute a java job, and got a Exception about Mysql deadlock.
Caused by: com.mysql.cj.jdbc.exceptions.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:124)
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916)
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354)
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:48)
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:75)
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 org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:197)
... 25 more
At first ,we think it’s a normal deadlock condition.
Finally,we found Deadlock may comes from select ... for update
.
We use command show engine innodb status
to show deadlock information, like this:
=====================================
2024-12-27 02:51:05 140067749193472 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 11 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 655234 srv_active, 0 srv_shutdown, 5905739 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2518134
OS WAIT ARRAY INFO: signal count 1539007
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------------------
LATEST DETECTED DEADLOCK
------------------------
2024-12-27 02:24:16 140068337477376
*** (1) TRANSACTION:
TRANSACTION 3165095, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
MySQL thread id 13899, OS thread handle 140066175198976, query id 19098873 192.168.10.195 root update
INSERT INTO `daily_statistic_data_2021`
(`imei`,`last_calculate_time`,`year`,`month`,`day`,`di1`,`di2`,`di3`,`di4`,`di5`,`di6`,`di7`,`di8`,`do1`,`do2`,`do3`,`do4`,`do5`,`do6`,`do7`,`do8`)
values ('861213052219265','2021-09-01 17:57:07','2021','09','01',0.0,0.0,0.0,13000.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0)
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 376 page no 5 n bits 72 index daily_statistic_data_unique of table `es`.`daily_statistic_data_2021` trx id 3165095 lock_mode X locks gap before rec
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 15; hex 383633383636303439373932383135; asc 863866049792815;;
1: len 4; hex 32303231; asc 2021;;
2: len 2; hex 3038; asc 08;;
3: len 2; hex 3235; asc 25;;
4: len 8; hex 8000000000000001; asc ;;
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 376 page no 5 n bits 72 index daily_statistic_data_unique of table `es`.`daily_statistic_data_2021` trx id 3165095 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 15; hex 383633383636303439373932383135; asc 863866049792815;;
1: len 4; hex 32303231; asc 2021;;
2: len 2; hex 3038; asc 08;;
3: len 2; hex 3235; asc 25;;
4: len 8; hex 8000000000000001; asc ;;
*** (2) TRANSACTION:
TRANSACTION 3165096, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
MySQL thread id 13904, OS thread handle 140066184709888, query id 19098879 192.168.10.193 root update
INSERT INTO `daily_statistic_data_2021`
(`imei`,`last_calculate_time`,`year`,`month`,`day`,`di1`,`di2`,`di3`,`di4`,`di5`,`di6`,`di7`,`di8`,`do1`,`do2`,`do3`,`do4`,`do5`,`do6`,`do7`,`do8`)
values ('861213050685368','2021-09-01 21:56:28','2021','09','01',0.0,0.0,0.0,19000.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 376 page no 5 n bits 72 index daily_statistic_data_unique of table `es`.`daily_statistic_data_2021` trx id 3165096 lock_mode X locks gap before rec
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 15; hex 383633383636303439373932383135; asc 863866049792815;;
1: len 4; hex 32303231; asc 2021;;
2: len 2; hex 3038; asc 08;;
3: len 2; hex 3235; asc 25;;
4: len 8; hex 8000000000000001; asc ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 376 page no 5 n bits 72 index daily_statistic_data_unique of table `es`.`daily_statistic_data_2021` trx id 3165096 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
0: len 15; hex 383633383636303439373932383135; asc 863866049792815;;
1: len 4; hex 32303231; asc 2021;;
2: len 2; hex 3038; asc 08;;
3: len 2; hex 3235; asc 25;;
4: len 8; hex 8000000000000001; asc ;;
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 3179361
Purge done for trx's n:o < 3179361 undo n:o < 0 state: running but idle
History list length 40
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421543863828424, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863827616, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863823576, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863824384, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863826808, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863826000, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863825192, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863822768, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421543863821960, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
// ignore IO information
Interesting is that: trx 3165095 waiting for lock from itself! How?
logic of Java job is that:
1. select ... for update;
2. if(!exist)
insert a new record;
else
update record;
3. commit;
Normally, Session-1 execute select ... where condition=1 for update
(without release it) , then Session-2 execute select ... where condition=1 for update
will waiting lock until timeout(without using SKIP LOCKED).
But fact is not. we test show that: If table is empty. Session-1 and Session-2 execute select ... for update
will retrun immediately :
Then we execute insert operation will get a Deadlock(Session-1 success,Session-2 fail),even lock different records :
If table is not empty ,it works well (normal-appearing):
May be implementation of select...for update
semantics is different between table is empty or not. And we can’t found correlative information from mysql Documentation-locking reads