Description:
Apparently, ANALYZE changes MySQL table locks in other threads.
This makes problems when it is used with InnoDB tables.
How to repeat:
Problem can be repeated only when run with multiple threads concurrently.
One thread was left waiting for
an InnoDB row lock, and the other thread was waiting for a MySQL table lock,
apparently. When lock wait timeout had passed, the row lock thread got a lock wait
timeout and rolled back. That resolved the hang. Looks like ANALYZE
table changes the MySQL table lock modes of OTHER threads. As if the other
threads in that case would request full table locks! I do not understand why
this should be so. Looks like a bug in the MySQL table lock table, maybe in
the table lock wait algorithm.
mysql> show innodb status\G
*************************** 1. row ***************************
Status:
=====================================
040417 1:44:17 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 17 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 558397, signal count 538477
Mutex spin waits 85289351, rounds 263293160, OS waits 157417
RW-shared spins 422754, OS waits 74414; RW-excl spins 2690855, OS waits
236059
------------------------
LATEST FOREIGN KEY ERROR
------------------------
040417 1:43:57 Transaction:
TRANSACTION 0 2872325, ACTIVE 0 sec, process no 19588, OS thread id 49165
inserting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
19 lock struct(s), heap size 2496, undo log entries 13
MySQL thread id 6, query id 7586394 localhost heikki update
insert into ibtest11c (D, B, C) values (5, 'khdkkkkk' ,'khdkkkkk')
Foreign key constraint fails for table test/ibtest11c:
,
CONSTRAINT `0_75` FOREIGN KEY (`A`, `D`) REFERENCES `ibtest11a` (`A`, `D`)
ON DELETE CASCADE ON UPDATE CASCADE
Trying to add in child table, in index PRIMARY tuple:
0: len 4; hex 80000101; asc ....;; 1: len 4; hex 80000005; asc ....;; 2:
len 8; hex 6b68646b6b6b6b6b; asc khdkkkkk;; 3: len 6; hex 0000002bd405; asc
...+..;; 4: len 7; hex 800000003206a6; asc ....2..;; 5: len 8; hex
6b68646b6b6b6b6b; asc khdkkkkk;;
But in parent table test/ibtest11a, in index PRIMARY,
the closest match we can find is record:
RECORD: info bits 0 0: len 4; hex 800000f9; asc ....;; 1: len 4; hex
80000005; asc ....;; 2: len 9; hex 6b48646b6b6b6b6b6b; asc kHdkkkkkk;; 3:
len 6; hex 00000024c2cc; asc ...$..;; 4: len 7; hex 800000058b094e; asc
......N;; 5: len 9; hex 6b48646b6b6b6b6b6b; asc kHdkkkkkk;;
------------------------
LATEST DETECTED DEADLOCK
------------------------
040417 1:36:09
*** (1) TRANSACTION:
TRANSACTION 0 2409162, ACTIVE 0 sec, process no 19594, OS thread id 53262
starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 320
MySQL thread id 8, query id 5935151 localhost heikki updating
delete from ibtest11a where A = 74757
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 6029 n bits 280 table test/ibtest11a index
PRIMARY trx id 0 2409162 lock_mode X waiting
Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00;
asc supremum.;;
*** (2) TRANSACTION:
TRANSACTION 0 2409152, ACTIVE 0 sec, process no 19588, OS thread id 49165
inserting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
22 lock struct(s), heap size 2496, undo log entries 52
MySQL thread id 6, query id 5935158 localhost heikki update
insert into ibtest11a (D, B, C) values (5, 'khD' ,'khD')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 6029 n bits 272 table test/ibtest11a index
PRIMARY trx id 0 2409152 lock mode S
Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00;
asc supremum.;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 6029 n bits 280 table test/ibtest11a index
PRIMARY trx id 0 2409152 lock_mode X insert intention waiting
Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00;
asc supremum.;;
*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 0 2887130
Purge done for trx's n:o < 0 2875867 undo n:o < 0 0
Total number of lock structs in row lock hash table 19
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 19511, OS thread id 45068
MySQL thread id 9, query id 7619108 localhost heikki
show innodb status
---TRANSACTION 0 2887129, not started, process no 19489, OS thread id 36874
inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
MySQL thread id 1, query id 7619109 localhost heikki update
INSERT INTO alex1 VALUES(38, 38,
802,'aA11194','bb','c52878','d7678t','e688014f','g79738','h802',date_format(
'2001-04-03 12:54:22','%Y-%m-%d %H:%i'),7
---TRANSACTION 0 2887082, ACTIVE 1 sec, process no 19497, OS thread id 40971
inserting, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
3 lock struct(s), heap size 320, undo log entries 102
MySQL thread id 3, query id 7619059 localhost heikki update
INSERT INTO alex1 VALUES(66, 66,
614,'aA8358','bb','c80146','d3746t','e646098f','g68166','h614',date_format('
2001-04-03 12:54:22','%Y-%m-%d %H:%i'),7.
---TRANSACTION 0 2872326, ACTIVE 20 sec, process no 19594, OS thread id
53262 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 320
MySQL thread id 8, query id 7586341 localhost heikki Searching rows for
update
update ibtest11a set B = 'kHdkkkk' where A = 30252
------- TRX HAS BEEN WAITING 20 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 6029 n bits 376 table test/ibtest11a index
PRIMARY trx id 0 2872326 lock_mode X waiting
Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00;
asc supremum.;;
------------------
---TRANSACTION 0 2872325, ACTIVE 20 sec, process no 19588, OS thread id
49165
21 lock struct(s), heap size 2496, undo log entries 18
MySQL thread id 6, query id 7586785 localhost heikki Waiting for table
insert ignore into ibtest11b(d, b, c) select d, b, c from ibtest11a where a
> 72916 and a < 72926
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
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: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
3267 OS file reads, 46701 OS file writes, 20688 OS fsyncs
0.41 reads/s, 124050 avg bytes/read, 20.70 writes/s, 6.94 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 1, free list len 0, seg size 2,
222 inserts, 222 merged recs, 51 merges
Hash table size 207619, used cells 85349, node heap has 109 buffer(s)
9494.27 hash searches/s, 8578.08 non-hash searches/s
---
LOG
---
Log sequence number 0 2370396374
Log flushed up to 0 2370374704
Last checkpoint at 0 2358555682
0 pending log writes, 0 pending chkp writes
11080 log i/o's done, 2.41 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 82980320; in additional pool allocated 1587968
Buffer pool size 3200
Free buffers 1
Database pages 3090
Modified db pages 489
Pending reads 0
Pending writes: LRU 0, flush list 120, single page 0
Pages read 4913, created 119870, written 301511
3.12 reads/s, 22.76 creates/s, 144.11 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
Main thread process no. 19487, id 28680, state: sleeping
Number of rows inserted 5176674, updated 117069, deleted 71719, read 1630736
1626.79 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
Description: Apparently, ANALYZE changes MySQL table locks in other threads. This makes problems when it is used with InnoDB tables. How to repeat: Problem can be repeated only when run with multiple threads concurrently. One thread was left waiting for an InnoDB row lock, and the other thread was waiting for a MySQL table lock, apparently. When lock wait timeout had passed, the row lock thread got a lock wait timeout and rolled back. That resolved the hang. Looks like ANALYZE table changes the MySQL table lock modes of OTHER threads. As if the other threads in that case would request full table locks! I do not understand why this should be so. Looks like a bug in the MySQL table lock table, maybe in the table lock wait algorithm. mysql> show innodb status\G *************************** 1. row *************************** Status: ===================================== 040417 1:44:17 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 17 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 558397, signal count 538477 Mutex spin waits 85289351, rounds 263293160, OS waits 157417 RW-shared spins 422754, OS waits 74414; RW-excl spins 2690855, OS waits 236059 ------------------------ LATEST FOREIGN KEY ERROR ------------------------ 040417 1:43:57 Transaction: TRANSACTION 0 2872325, ACTIVE 0 sec, process no 19588, OS thread id 49165 inserting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 19 lock struct(s), heap size 2496, undo log entries 13 MySQL thread id 6, query id 7586394 localhost heikki update insert into ibtest11c (D, B, C) values (5, 'khdkkkkk' ,'khdkkkkk') Foreign key constraint fails for table test/ibtest11c: , CONSTRAINT `0_75` FOREIGN KEY (`A`, `D`) REFERENCES `ibtest11a` (`A`, `D`) ON DELETE CASCADE ON UPDATE CASCADE Trying to add in child table, in index PRIMARY tuple: 0: len 4; hex 80000101; asc ....;; 1: len 4; hex 80000005; asc ....;; 2: len 8; hex 6b68646b6b6b6b6b; asc khdkkkkk;; 3: len 6; hex 0000002bd405; asc ...+..;; 4: len 7; hex 800000003206a6; asc ....2..;; 5: len 8; hex 6b68646b6b6b6b6b; asc khdkkkkk;; But in parent table test/ibtest11a, in index PRIMARY, the closest match we can find is record: RECORD: info bits 0 0: len 4; hex 800000f9; asc ....;; 1: len 4; hex 80000005; asc ....;; 2: len 9; hex 6b48646b6b6b6b6b6b; asc kHdkkkkkk;; 3: len 6; hex 00000024c2cc; asc ...$..;; 4: len 7; hex 800000058b094e; asc ......N;; 5: len 9; hex 6b48646b6b6b6b6b6b; asc kHdkkkkkk;; ------------------------ LATEST DETECTED DEADLOCK ------------------------ 040417 1:36:09 *** (1) TRANSACTION: TRANSACTION 0 2409162, ACTIVE 0 sec, process no 19594, OS thread id 53262 starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 320 MySQL thread id 8, query id 5935151 localhost heikki updating delete from ibtest11a where A = 74757 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 6029 n bits 280 table test/ibtest11a index PRIMARY trx id 0 2409162 lock_mode X waiting Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00; asc supremum.;; *** (2) TRANSACTION: TRANSACTION 0 2409152, ACTIVE 0 sec, process no 19588, OS thread id 49165 inserting, thread declared inside InnoDB 499 mysql tables in use 1, locked 1 22 lock struct(s), heap size 2496, undo log entries 52 MySQL thread id 6, query id 5935158 localhost heikki update insert into ibtest11a (D, B, C) values (5, 'khD' ,'khD') *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 6029 n bits 272 table test/ibtest11a index PRIMARY trx id 0 2409152 lock mode S Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00; asc supremum.;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 6029 n bits 280 table test/ibtest11a index PRIMARY trx id 0 2409152 lock_mode X insert intention waiting Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00; asc supremum.;; *** WE ROLL BACK TRANSACTION (1) ------------ TRANSACTIONS ------------ Trx id counter 0 2887130 Purge done for trx's n:o < 0 2875867 undo n:o < 0 0 Total number of lock structs in row lock hash table 19 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 0, not started, process no 19511, OS thread id 45068 MySQL thread id 9, query id 7619108 localhost heikki show innodb status ---TRANSACTION 0 2887129, not started, process no 19489, OS thread id 36874 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 MySQL thread id 1, query id 7619109 localhost heikki update INSERT INTO alex1 VALUES(38, 38, 802,'aA11194','bb','c52878','d7678t','e688014f','g79738','h802',date_format( '2001-04-03 12:54:22','%Y-%m-%d %H:%i'),7 ---TRANSACTION 0 2887082, ACTIVE 1 sec, process no 19497, OS thread id 40971 inserting, thread declared inside InnoDB 500 mysql tables in use 1, locked 1 3 lock struct(s), heap size 320, undo log entries 102 MySQL thread id 3, query id 7619059 localhost heikki update INSERT INTO alex1 VALUES(66, 66, 614,'aA8358','bb','c80146','d3746t','e646098f','g68166','h614',date_format(' 2001-04-03 12:54:22','%Y-%m-%d %H:%i'),7. ---TRANSACTION 0 2872326, ACTIVE 20 sec, process no 19594, OS thread id 53262 starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 320 MySQL thread id 8, query id 7586341 localhost heikki Searching rows for update update ibtest11a set B = 'kHdkkkk' where A = 30252 ------- TRX HAS BEEN WAITING 20 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 6029 n bits 376 table test/ibtest11a index PRIMARY trx id 0 2872326 lock_mode X waiting Record lock, heap no 1 RECORD: info bits 0 0: len 9; hex 73757072656d756d00; asc supremum.;; ------------------ ---TRANSACTION 0 2872325, ACTIVE 20 sec, process no 19588, OS thread id 49165 21 lock struct(s), heap size 2496, undo log entries 18 MySQL thread id 6, query id 7586785 localhost heikki Waiting for table insert ignore into ibtest11b(d, b, c) select d, b, c from ibtest11a where a > 72916 and a < 72926 -------- FILE I/O -------- I/O thread 0 state: waiting for i/o request (insert buffer thread) 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: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 3267 OS file reads, 46701 OS file writes, 20688 OS fsyncs 0.41 reads/s, 124050 avg bytes/read, 20.70 writes/s, 6.94 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf for space 0: size 1, free list len 0, seg size 2, 222 inserts, 222 merged recs, 51 merges Hash table size 207619, used cells 85349, node heap has 109 buffer(s) 9494.27 hash searches/s, 8578.08 non-hash searches/s --- LOG --- Log sequence number 0 2370396374 Log flushed up to 0 2370374704 Last checkpoint at 0 2358555682 0 pending log writes, 0 pending chkp writes 11080 log i/o's done, 2.41 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 82980320; in additional pool allocated 1587968 Buffer pool size 3200 Free buffers 1 Database pages 3090 Modified db pages 489 Pending reads 0 Pending writes: LRU 0, flush list 120, single page 0 Pages read 4913, created 119870, written 301511 3.12 reads/s, 22.76 creates/s, 144.11 writes/s Buffer pool hit rate 1000 / 1000 -------------- ROW OPERATIONS -------------- 1 queries inside InnoDB, 0 queries in queue Main thread process no. 19487, id 28680, state: sleeping Number of rows inserted 5176674, updated 117069, deleted 71719, read 1630736 1626.79 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================