Description:
There are lots parallel to operation Mysql Innodb table with SQL:
begin
insert ... ;
...
500 inserts
...
insert ... ;
commit;
And this situation rarely occur.
Actually, The question is :
Normally, The AUTO-INC LOCK is just only can handled by one transaction/insert ,
And the Deadlock need two transaction both holds the lock at the same time and to wait each other.
But , How the situation occured ?
Pls Help me to analyse clearly.
How to repeat:
(root@im_newlog4a:)[(none)]> show engine innodb status \G
*************************** 1. row ***************************
Status:
=====================================
091124 18:07:27 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 55 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 568544859, signal count 410475613
--Thread 1211971936 has waited at ../include/log0log.ic line 315 for 0.00 seconds the semaphore:
Mutex at 0x2ac9b0b910 created file log0log.c line 744, lock var 1
waiters flag 0
--Thread 1247648096 has waited at ../include/log0log.ic line 315 for 0.00 seconds the semaphore:
Mutex at 0x2ac9b0b910 created file log0log.c line 744, lock var 1
waiters flag 0
Mutex spin waits 0, rounds 35626241599, OS waits 371074456
RW-shared spins 180954456, OS waits 88191643; RW-excl spins 91992164, OS waits 71197598
------------------------
LATEST DETECTED DEADLOCK
------------------------
091124 18:04:58
*** (1) TRANSACTION:
TRANSACTION 2 1757811763, ACTIVE 1 sec, process no 2289, OS thread id 1169373536 setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 1 lock struct(s), heap size 368
MySQL thread id 1074298, query id 10176734566 172.18.8.219 aliim update
insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 15:41:33','cnalichnshowcorp','-1958381443','6.16.04','0')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811763 lock mode AUTO-INC waiting
*** (2) TRANSACTION:
TRANSACTION 2 1757809862, ACTIVE 13 sec, process no 2289, OS thread id 1273739616 inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
2 lock struct(s), heap size 3024, undo log entries 13
MySQL thread id 1071849, query id 10176734567 172.18.8.220 aliim update
insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 16:10:22','cntaobaosgf130','-212660782','6.16.04','0')
*** (2) HOLDS THE LOCK(S):
TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757809862 lock mode AUTO-INC
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811877 lock mode AUTO-INC waiting
TOO DEEP OR LONG SEARCH IN THE LOCK TABLE WAITS-FOR GRAPH
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 2 1757836657
Purge done for trx's n:o < 2 1750646447 undo n:o < 0 0
History list length 7
Total number of lock structs in row lock hash table 0
... truncated...
process no 2289, OS thread id 1186679136 setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1216, undo log entries 2
MySQL thread id 1074214, query id 10176886677 172.18.8.158 aliim update
insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 18:07:20','cntaobao????????','0','','1')
------- TRX HAS BEEN WAITING 1 SEC FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757835228 lock mode AUTO-INC waiting
------------------
..................
---TRANSACTION 2 1757811796, ACTIVE 150 sec, process no 2289, OS thread id 1253771616 setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 14320, undo log entries 92
MySQL thread id 1074283, query id 10176886975 172.18.8.219 aliim update
insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 15:52:23','cntaobaofuxincld','0','','1')
------- TRX HAS BEEN WAITING 1 SEC FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811796 lock mode AUTO-INC waiting
------------------
---TRANSACTION 2 1757811763, ACTIVE 150 sec, process no 2289, OS thread id 1169373536 setting auto-inc lock
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 14320, undo log entries 92
MySQL thread id 1074298, query id 10176885184 172.18.8.219 aliim update
insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 15:41:39','cntaobaomengli521241','0','','1')
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811763 lock mode AUTO-INC waiting
------------------
... ...
------------------
---TRANSACTION 2 1750652302, ACTIVE 28353 sec, process no 2289, OS thread id 1254304096
MySQL thread id 1072048, query id 10176866805 172.18.166.119 aliim
--------
FILE I/O
--------
I/O thread 0 state: doing file i/o (insert buffer thread) ev set
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 42, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1300037751 OS file reads, 4887428241 OS file writes, 113246983 OS fsyncs
3 pending preads, 0 pending pwrites
273.23 reads/s, 18429 avg bytes/read, 447.26 writes/s, 2.96 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 149143, free list len 228078, seg size 377222,
2413161251 inserts, 2420895507 merged recs, 101610202 merges
Hash table size 17700857, used cells 978258, node heap has 1486 buffer(s)
1037.74 hash searches/s, 2606.46 non-hash searches/s
---
LOG
---
Log sequence number 1521 448642462
Log flushed up to 1521 448450864
Last checkpoint at 1520 3258093855
0 pending log writes, 0 pending chkp writes
4292808761 log i/o's done, 439.86 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 10366554119; in additional pool allocated 420888576
Buffer pool size 524288
Free buffers 0
Database pages 522802
Modified db pages 73203
Pending reads 14
Pending writes: LRU 0, flush list 0, single page 0
Pages read 2779143027, created 77186523, written 790366861
313.46 reads/s, 14.20 creates/s, 21.70 writes/s
Buffer pool hit rate 983 / 1000
--------------
ROW OPERATIONS
--------------
8 queries inside InnoDB, 11 queries in queue
2 read views open inside InnoDB
Main thread process no. 2289, id 1157658976, state: sleeping
Number of rows inserted 5830066209, updated 1229522, deleted 150799838, read 4596986520
1091.25 inserts/s, 0.00 updates/s, 0.00 deletes/s, 149.71 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.10 sec)
Description: There are lots parallel to operation Mysql Innodb table with SQL: begin insert ... ; ... 500 inserts ... insert ... ; commit; And this situation rarely occur. Actually, The question is : Normally, The AUTO-INC LOCK is just only can handled by one transaction/insert , And the Deadlock need two transaction both holds the lock at the same time and to wait each other. But , How the situation occured ? Pls Help me to analyse clearly. How to repeat: (root@im_newlog4a:)[(none)]> show engine innodb status \G *************************** 1. row *************************** Status: ===================================== 091124 18:07:27 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 55 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 568544859, signal count 410475613 --Thread 1211971936 has waited at ../include/log0log.ic line 315 for 0.00 seconds the semaphore: Mutex at 0x2ac9b0b910 created file log0log.c line 744, lock var 1 waiters flag 0 --Thread 1247648096 has waited at ../include/log0log.ic line 315 for 0.00 seconds the semaphore: Mutex at 0x2ac9b0b910 created file log0log.c line 744, lock var 1 waiters flag 0 Mutex spin waits 0, rounds 35626241599, OS waits 371074456 RW-shared spins 180954456, OS waits 88191643; RW-excl spins 91992164, OS waits 71197598 ------------------------ LATEST DETECTED DEADLOCK ------------------------ 091124 18:04:58 *** (1) TRANSACTION: TRANSACTION 2 1757811763, ACTIVE 1 sec, process no 2289, OS thread id 1169373536 setting auto-inc lock mysql tables in use 1, locked 1 LOCK WAIT 1 lock struct(s), heap size 368 MySQL thread id 1074298, query id 10176734566 172.18.8.219 aliim update insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 15:41:33','cnalichnshowcorp','-1958381443','6.16.04','0') *** (1) WAITING FOR THIS LOCK TO BE GRANTED: TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811763 lock mode AUTO-INC waiting *** (2) TRANSACTION: TRANSACTION 2 1757809862, ACTIVE 13 sec, process no 2289, OS thread id 1273739616 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 2 lock struct(s), heap size 3024, undo log entries 13 MySQL thread id 1071849, query id 10176734567 172.18.8.220 aliim update insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 16:10:22','cntaobaosgf130','-212660782','6.16.04','0') *** (2) HOLDS THE LOCK(S): TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757809862 lock mode AUTO-INC *** (2) WAITING FOR THIS LOCK TO BE GRANTED: TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811877 lock mode AUTO-INC waiting TOO DEEP OR LONG SEARCH IN THE LOCK TABLE WAITS-FOR GRAPH *** WE ROLL BACK TRANSACTION (2) ------------ TRANSACTIONS ------------ Trx id counter 2 1757836657 Purge done for trx's n:o < 2 1750646447 undo n:o < 0 0 History list length 7 Total number of lock structs in row lock hash table 0 ... truncated... process no 2289, OS thread id 1186679136 setting auto-inc lock mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1216, undo log entries 2 MySQL thread id 1074214, query id 10176886677 172.18.8.158 aliim update insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 18:07:20','cntaobao????????','0','','1') ------- TRX HAS BEEN WAITING 1 SEC FOR THIS LOCK TO BE GRANTED: TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757835228 lock mode AUTO-INC waiting ------------------ .................. ---TRANSACTION 2 1757811796, ACTIVE 150 sec, process no 2289, OS thread id 1253771616 setting auto-inc lock mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 14320, undo log entries 92 MySQL thread id 1074283, query id 10176886975 172.18.8.219 aliim update insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 15:52:23','cntaobaofuxincld','0','','1') ------- TRX HAS BEEN WAITING 1 SEC FOR THIS LOCK TO BE GRANTED: TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811796 lock mode AUTO-INC waiting ------------------ ---TRANSACTION 2 1757811763, ACTIVE 150 sec, process no 2289, OS thread id 1169373536 setting auto-inc lock mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 14320, undo log entries 92 MySQL thread id 1074298, query id 10176885184 172.18.8.219 aliim update insert into im_user_sys_200911(TIME,LOGIN_ID,IP,CLIENT_VERSION,ACTION_TYPE) values('2009-11-24 15:41:39','cntaobaomengli521241','0','','1') ------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED: TABLE LOCK table `ctulog/im_user_sys_200911` trx id 2 1757811763 lock mode AUTO-INC waiting ------------------ ... ... ------------------ ---TRANSACTION 2 1750652302, ACTIVE 28353 sec, process no 2289, OS thread id 1254304096 MySQL thread id 1072048, query id 10176866805 172.18.166.119 aliim -------- FILE I/O -------- I/O thread 0 state: doing file i/o (insert buffer thread) ev set I/O thread 1 state: waiting for i/o request (log thread) I/O thread 2 state: waiting for i/o request (read thread) I/O thread 3 state: waiting for i/o request (write thread) Pending normal aio reads: 0, aio writes: 0, ibuf aio reads: 42, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 1300037751 OS file reads, 4887428241 OS file writes, 113246983 OS fsyncs 3 pending preads, 0 pending pwrites 273.23 reads/s, 18429 avg bytes/read, 447.26 writes/s, 2.96 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 149143, free list len 228078, seg size 377222, 2413161251 inserts, 2420895507 merged recs, 101610202 merges Hash table size 17700857, used cells 978258, node heap has 1486 buffer(s) 1037.74 hash searches/s, 2606.46 non-hash searches/s --- LOG --- Log sequence number 1521 448642462 Log flushed up to 1521 448450864 Last checkpoint at 1520 3258093855 0 pending log writes, 0 pending chkp writes 4292808761 log i/o's done, 439.86 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 10366554119; in additional pool allocated 420888576 Buffer pool size 524288 Free buffers 0 Database pages 522802 Modified db pages 73203 Pending reads 14 Pending writes: LRU 0, flush list 0, single page 0 Pages read 2779143027, created 77186523, written 790366861 313.46 reads/s, 14.20 creates/s, 21.70 writes/s Buffer pool hit rate 983 / 1000 -------------- ROW OPERATIONS -------------- 8 queries inside InnoDB, 11 queries in queue 2 read views open inside InnoDB Main thread process no. 2289, id 1157658976, state: sleeping Number of rows inserted 5830066209, updated 1229522, deleted 150799838, read 4596986520 1091.25 inserts/s, 0.00 updates/s, 0.00 deletes/s, 149.71 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ 1 row in set (0.10 sec)