MySQL patches by Codership

Bug #428958
Comment #3

Comment 3 for bug 428958

Revision history for this message

Seppo Jaakola (seppo-jaakola) wrote on 2009-09-26:

The issue was reproduced with innodb_lock_wait_timeout set to high value. Then it is possible to catch the
BF applier while still waiting for the local lock. Here is innodb status, from the hanging situation:

=====================================
090926 22:46:40 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 45 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 13, signal count 13
Mutex spin waits 0, rounds 165, OS waits 6
RW-shared spins 10, OS waits 5; RW-excl spins 2, OS waits 2
------------
TRANSACTIONS
------------
Trx id counter 0 88404
Purge done for trx's n:o < 0 88384 undo n:o < 0 0
History list length 9
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 6115, OS thread id 140204650731856
MySQL thread id 21, query id 519 bengal 10.0.0.122 root
show innodb status
---TRANSACTION 0 88403, ACTIVE 243 sec, process no 6115, OS thread id 140204650998096 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 1
MySQL thread id 13, query id 505 10.0.0.101 root Updating
UPDATE comm00 SET x = (x + 1) % 65537, y = ((y*x % 65537) + (43086*y % 65537) + (y*z % 65537)) % 65537, z = ((z*x % 65537) + (z*y % 65537) + (43086*z % 65537)) % 65537, r = 0.041111 WHERE p = 0
Trx read view will not see trx with id >= 0 88404, sees < 0 88382
------- TRX HAS BEEN WAITING 243 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 50 n bits 72 index `PRIMARY` of table `test`.`comm00` trx id 0 88403 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
0: len 4; hex 80000000; asc ;; 1: len 6; hex 000000015946; asc YF;; 2: len 7; hex 000000003608d9; asc 6 ;; 3: len 4; hex 8000000b; asc ;; 4: len 4; hex 80009455; asc U;; 5: len 4; hex 80000507; asc ;; 6: len 8; hex 60b1868bdc53e33f; asc ` S ?;;

------------------
---TRANSACTION 0 88402, ACTIVE 243 sec, process no 6115, OS thread id 140204651264336 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 1
MySQL thread id 12, query id 497 10.0.0.101 root Updating
UPDATE comm01 SET x = (x + 1) % 65537, y = ((y*x % 65537) + (51377*y % 65537) + (y*z % 65537)) % 65537, z = ((z*x % 65537) + (z*y % 65537) + (51377*z % 65537)) % 65537, r = 0.884950 WHERE p = 3
Trx read view will not see trx with id >= 0 88403, sees < 0 88382
------- TRX HAS BEEN WAITING 243 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 51 n bits 72 index `PRIMARY` of table `test`.`comm01` trx id 0 88402 lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
0: len 4; hex 80000003; asc ;; 1: len 6; hex 00000001594b; asc YK;; 2: len 7; hex 000000013b2fbb; asc ;/ ;; 3: len 4; hex 8000000d; asc ;; 4: len 4; hex 80007bf8; asc { ;; 5: len 4; hex 8000b3a9; asc ;; 6: len 8; hex babe0f0709519e3f; asc Q ?;;

------------------
---TRANSACTION 0 88400, ACTIVE 243 sec, process no 6115, OS thread id 140205247015248 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 1, query id 477 invalidating query cache entries (table)
------- TRX HAS BEEN WAITING 243 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 52 n bits 72 index `PRIMARY` of table `test`.`comm02` trx id 0 88400 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
0: len 4; hex 80000002; asc ;; 1: len 6; hex 000000015938; asc Y8;; 2: len 7; hex 00000001372785; asc 7' ;; 3: len 4; hex 8000000b; asc ;; 4: len 4; hex 800041a8; asc A ;; 5: len 4; hex 80006eea; asc n ;; 6: len 8; hex b7ec10ffb0a5ea3f; asc ?;;

------------------
---TRANSACTION 0 88395, ACTIVE 243 sec, process no 6115, OS thread id 140204650465616
2 lock struct(s), heap size 368, 1 row lock(s), undo log entries 1
MySQL thread id 15, query id 504 10.0.0.101 root
COMMIT
Trx read view will not see trx with id >= 0 88396, sees < 0 88382
---TRANSACTION 0 88390, ACTIVE 243 sec, process no 6115, OS thread id 140204650199376
2 lock struct(s), heap size 368, 3 row lock(s), undo log entries 3
MySQL thread id 16, query id 496 10.0.0.101 root
COMMIT
Trx read view will not see trx with id >= 0 88391, sees < 0 88378
---TRANSACTION 0 88382, ACTIVE 243 sec, process no 6115, OS thread id 140204651530576
8 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 4
MySQL thread id 11, query id 503 10.0.0.101 root
COMMIT
Trx read view will not see trx with id >= 0 88383, sees < 0 88361
--------
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
32 OS file reads, 32 OS file writes, 22 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 871679, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 13158549
Log flushed up to 0 13158549
Last checkpoint at 0 13158549
0 pending log writes, 0 pending chkp writes
23 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 502961626; in additional pool allocated 917248
Dictionary memory allocated 49792
Buffer pool size 26880
Free buffers 26810
Database pages 69
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 69, created 0, written 35
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
6 read views open inside InnoDB
Main thread process no. 6115, id 140204682103120, state: waiting for server activity
Number of rows inserted 16, updated 49, deleted 0, read 184
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

=====================================
090926 22:46:40 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 45 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 13, signal count 13
Mutex spin waits 0, rounds 165, OS waits 6
RW-shared spins 10, OS waits 5; RW-excl spins 2, OS waits 2
------------
TRANSACTIONS
------------
Trx id counter 0 88404
Purge done for trx's n:o < 0 88384 undo n:o < 0 0
History list length 9
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 6115, OS thread id 140204650731856
MySQL thread id 21, query id 519 bengal 10.0.0.122 root
show innodb status
---TRANSACTION 0 88403, ACTIVE 243 sec, process no 6115, OS thread id 140204650998096 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 1
MySQL thread id 13, query id 505 10.0.0.101 root Updating
UPDATE comm00 SET x = (x + 1) % 65537, y = ((y*x % 65537) + (43086*y % 65537) + (y*z % 65537)) % 65537, z = ((z*x % 65537) + (z*y % 65537) + (43086*z % 65537)) % 65537, r = 0.041111 WHERE p = 0
Trx read view will not see trx with id >= 0 88404, sees < 0 88382
------- TRX HAS BEEN WAITING 243 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 50 n bits 72 index `PRIMARY` of table `test`.`comm00` trx id 0 88403 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000000; asc     ;; 1: len 6; hex 000000015946; asc     YF;; 2: len 7; hex 000000003608d9; asc     6  ;; 3: len 4; hex 8000000b; asc     ;; 4: len 4; hex 80009455; asc    U;; 5: len 4; hex 80000507; asc     ;; 6: len 8; hex 60b1868bdc53e33f; asc `    S ?;;

------------------
---TRANSACTION 0 88402, ACTIVE 243 sec, process no 6115, OS thread id 140204651264336 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1216, 2 row lock(s), undo log entries 1
MySQL thread id 12, query id 497 10.0.0.101 root Updating
UPDATE comm01 SET x = (x + 1) % 65537, y = ((y*x % 65537) + (51377*y % 65537) + (y*z % 65537)) % 65537, z = ((z*x % 65537) + (z*y % 65537) + (51377*z % 65537)) % 65537, r = 0.884950 WHERE p = 3
Trx read view will not see trx with id >= 0 88403, sees < 0 88382
------- TRX HAS BEEN WAITING 243 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 51 n bits 72 index `PRIMARY` of table `test`.`comm01` trx id 0 88402 lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000003; asc     ;; 1: len 6; hex 00000001594b; asc     YK;; 2: len 7; hex 000000013b2fbb; asc     ;/ ;; 3: len 4; hex 8000000d; asc     ;; 4: len 4; hex 80007bf8; asc   { ;; 5: len 4; hex 8000b3a9; asc     ;; 6: len 8; hex babe0f0709519e3f; asc      Q ?;;

------------------
---TRANSACTION 0 88400, ACTIVE 243 sec, process no 6115, OS thread id 140205247015248 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 368, 1 row lock(s)
MySQL thread id 1, query id 477 invalidating query cache entries (table)
------- TRX HAS BEEN WAITING 243 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 52 n bits 72 index `PRIMARY` of table `test`.`comm02` trx id 0 88400 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 7; compact format; info bits 0
 0: len 4; hex 80000002; asc     ;; 1: len 6; hex 000000015938; asc     Y8;; 2: len 7; hex 00000001372785; asc     7' ;; 3: len 4; hex 8000000b; asc     ;; 4: len 4; hex 800041a8; asc   A ;; 5: len 4; hex 80006eea; asc   n ;; 6: len 8; hex b7ec10ffb0a5ea3f; asc        ?;;

------------------
---TRANSACTION 0 88395, ACTIVE 243 sec, process no 6115, OS thread id 140204650465616
2 lock struct(s), heap size 368, 1 row lock(s), undo log entries 1
MySQL thread id 15, query id 504 10.0.0.101 root
COMMIT
Trx read view will not see trx with id >= 0 88396, sees < 0 88382
---TRANSACTION 0 88390, ACTIVE 243 sec, process no 6115, OS thread id 140204650199376
2 lock struct(s), heap size 368, 3 row lock(s), undo log entries 3
MySQL thread id 16, query id 496 10.0.0.101 root
COMMIT
Trx read view will not see trx with id >= 0 88391, sees < 0 88378
---TRANSACTION 0 88382, ACTIVE 243 sec, process no 6115, OS thread id 140204651530576
8 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 4
MySQL thread id 11, query id 503 10.0.0.101 root
COMMIT
Trx read view will not see trx with id >= 0 88383, sees < 0 88361
--------
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
32 OS file reads, 32 OS file writes, 22 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 871679, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 0 13158549
Log flushed up to   0 13158549
Last checkpoint at  0 13158549
0 pending log writes, 0 pending chkp writes
23 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 502961626; in additional pool allocated 917248
Dictionary memory allocated 49792
Buffer pool size   26880
Free buffers       26810
Database pages     69
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 69, created 0, written 35
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
6 read views open inside InnoDB
Main thread process no. 6115, id 140204682103120, state: waiting for server activity
Number of rows inserted 16, updated 49, deleted 0, read 184
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================