Jan Lindström (Inactive) added a comment - 2014-10-03 16:30 InnoDB transaction log: ===================================== 141003 16:21:20 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 20 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 872 1_second, 872 sleeps, 78 10_second, 95 background, 95 flush srv_master_thread log flush and writes: 2095 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 3244, signal count 3213 Mutex spin waits 1154, rounds 96727, OS waits 3089 RW-shared spins 108, rounds 2575, OS waits 80 RW-excl spins 6, rounds 2145, OS waits 65 Spin rounds per wait: 83.82 mutex, 23.84 RW-shared, 357.50 RW-excl -------- FILE I/O -------- I/O thread 0 state: waiting for completed aio requests (insert buffer thread) I/O thread 1 state: waiting for completed aio requests (log thread) I/O thread 2 state: waiting for completed aio requests (read thread) I/O thread 3 state: waiting for completed aio requests (read thread) I/O thread 4 state: waiting for completed aio requests (read thread) I/O thread 5 state: waiting for completed aio requests (read thread) I/O thread 6 state: waiting for completed aio requests (write thread) I/O thread 7 state: waiting for completed aio requests (write thread) I/O thread 8 state: waiting for completed aio requests (write thread) I/O thread 9 state: waiting for completed aio requests (write thread) Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] , ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 284 OS file reads, 4958 OS file writes, 1823 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 merges merged operations: insert 0, delete mark 0, delete 0 discarded operations: insert 0, delete mark 0, delete 0 Hash table size 276671, node heap has 2 buffer(s) 0.00 hash searches/s, 0.00 non-hash searches/s --- LOG --- Log sequence number 2735953 Log flushed up to 2735953 Last checkpoint at 2735953 Max checkpoint age 7782360 Checkpoint age target 7539162 Modified age 0 Checkpoint age 0 0 pending log writes, 0 pending chkp writes 1654 log i/o's done, 0.00 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 137756672; in additional pool allocated 0 Total memory allocated by read views 760 Internal hash tables (constant factor + variable factor) Adaptive hash index 2250352 (2213368 + 36984) Page hash 139112 (buffer pool 0 only) Dictionary cache 717229 (554768 + 162461) File system 83536 (82672 + 864) Lock system 344944 (332872 + 12072) Recovery system 0 (0 + 0) Dictionary memory allocated 162461 Buffer pool size 8191 Buffer pool size, bytes 134201344 Free buffers 7745 Database pages 444 Old database pages 0 Modified db pages 0 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages made young 0, not young 0 0.00 youngs/s, 0.00 non-youngs/s Pages read 145, created 299, written 3199 0.00 reads/s, 0.00 creates/s, 0.00 writes/s No buffer pool page gets since the last printout Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s LRU len: 444, unzip_LRU len: 0 I/O sum[0]:cur[0], unzip sum[0]:cur[0] -------------- ROW OPERATIONS -------------- 0 queries inside InnoDB, 0 queries in queue 2 read views open inside InnoDB 5 transactions active inside InnoDB 5 out of 1000 descriptors used ---OLDEST VIEW--- Normal read view Read view low limit trx n:o B2F Read view up limit trx id AE4 Read view low limit trx id B2F Read view individually stored trx ids: Read view trx id B2E Read view trx id B2D Read view trx id B29 Read view trx id B1B Read view trx id B02 Read view trx id AFF Read view trx id AE4 ----------------- Main thread process no. 22083, id 140206485255936, state: waiting for server activity Number of rows inserted 1650, updated 1450, deleted 491, read 45755 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s ------------------------ LATEST DETECTED DEADLOCK ------------------------ 141003 13:41:06 *** (1) TRANSACTION: TRANSACTION B1B, ACTIVE 306 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 13 lock struct(s), heap size 3112, 5 row lock(s), undo log entries 3 MySQL thread id 9, OS thread handle 0x7f849059a700, query id 2846 localhost 127.0.0.1 root init DELETE LOW_PRIORITY QUICK IGNORE FROM `table2_int_autoinc` ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 2 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 334 n bits 184 index `PRIMARY` of table `test`.`table2_int_autoinc` trx id B1B lock_mode X locks rec but not gap waiting *** (2) TRANSACTION: TRANSACTION AFF, ACTIVE 611 sec fetching rows mysql tables in use 4, locked 4 32 lock struct(s), heap size 6960, 123 row lock(s), undo log entries 6 MySQL thread id 8, OS thread handle 0x7f8491c67700, query id 2849 localhost 127.0.0.1 root executing DELETE LOW_PRIORITY FROM `table1_key_pk_parts_2_int_autoinc` WHERE `col_char_12_key` IN ( SELECT `col_char_12_key` FROM `table2_key_pk_parts_2_int_autoinc` WHERE `pk` = 2 ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 2 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 334 n bits 176 index `PRIMARY` of table `test`.`table2_int_autoinc` trx id AFF lock_mode X locks rec but not gap *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 329 n bits 144 index `PRIMARY` of table `test`.`table1_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id AFF lock_mode X locks rec but not gap waiting *** WE ROLL BACK TRANSACTION (1) ------------ TRANSACTIONS ------------ Trx id counter B37 Purge done for trx's n:o < B28 undo n:o < 0 History list length 211 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION B2F, ACTIVE 9736 sec mysql tables in use 2, locked 2 2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1 MySQL thread id 12, OS thread handle 0x7f84904bf700, query id 2829 localhost 127.0.0.1 root query end INSERT LOW_PRIORITY INTO `table0_key_pk_parts_2_int_autoinc` (`pk`) VALUES (NULL) TABLE LOCK table `test`.`table0_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B2F lock mode IX RECORD LOCKS space id 0 page no 315 n bits 152 index `PRIMARY` of table `test`.`table0_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B2F lock_mode X locks rec but not gap ---TRANSACTION B2E, ACTIVE 9767 sec mysql tables in use 1, locked 1 1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1 MySQL thread id 14, OS thread handle 0x7f848f1f6700, query id 2826 localhost 127.0.0.1 root query end REPLACE LOW_PRIORITY INTO `table100_int_autoinc` (`pk`) VALUES (NULL) TABLE LOCK table `test`.`table100_int_autoinc` trx id B2E lock mode IX ---TRANSACTION B29, ACTIVE 9818 sec starting index read mysql tables in use 2, locked 2 LOCK WAIT 3 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 2 MySQL thread id 2, OS thread handle 0x7f8491d9b700, query id 2808 Update_rows_log_event::find_row(783) ------- TRX HAS BEEN WAITING 9818 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 373 n bits 248 index `PRIMARY` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B29 lock_mode X locks rec but not gap waiting ------------------ TABLE LOCK table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B29 lock mode IX RECORD LOCKS space id 0 page no 373 n bits 248 index `PRIMARY` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B29 lock_mode X locks rec but not gap RECORD LOCKS space id 0 page no 373 n bits 248 index `PRIMARY` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B29 lock_mode X locks rec but not gap waiting ---TRANSACTION B1B, ACTIVE 9920 sec 16 lock struct(s), heap size 3112, 5 row lock(s), undo log entries 3 MySQL thread id 9, OS thread handle 0x7f849059a700, query id 2887 localhost 127.0.0.1 root sleeping COMMIT Trx read view will not see trx with id >= B30, sees < AE4 TABLE LOCK table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id B1B lock mode IX RECORD LOCKS space id 0 page no 371 n bits 128 index `col_int_key` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id B1B lock_mode X locks rec but not gap RECORD LOCKS space id 0 page no 368 n bits 120 index `PRIMARY` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id B1B lock_mode X locks rec but not gap TABLE LOCK table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B1B lock mode IX RECORD LOCKS space id 0 page no 375 n bits 176 index `col_int_key` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B1B lock_mode X locks rec but not gap RECORD LOCKS space id 0 page no 373 n bits 248 index `PRIMARY` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B1B lock_mode X locks rec but not gap TABLE LOCK table `test`.`table1_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id B1B lock mode IX TABLE LOCK table `test`.`table10_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id B1B lock mode IX RECORD LOCKS space id 0 page no 355 n bits 112 index `col_char_12_key` of table `test`.`table10_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id B1B lock_mode X locks rec but not gap TABLE LOCK table `test`.`table1_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id B1B lock mode IX TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS ---TRANSACTION AE4, ACTIVE 10276 sec 31 lock struct(s), heap size 6960, 247 row lock(s), undo log entries 26 MySQL thread id 11, OS thread handle 0x7f8490508700, query id 2825 localhost 127.0.0.1 root sleeping COMMIT TABLE LOCK table `test`.`table2_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id AE4 lock mode IX RECORD LOCKS space id 0 page no 341 n bits 112 index `col_int_key` of table `test`.`table2_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id AE4 lock_mode X locks rec but not gap RECORD LOCKS space id 0 page no 339 n bits 144 index `PRIMARY` of table `test`.`table2_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id AE4 lock_mode X locks rec but not gap TABLE LOCK table `test`.`table2_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id AE4 lock mode IX RECORD LOCKS space id 0 page no 345 n bits 112 index `col_int_key` of table `test`.`table2_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id AE4 lock_mode X locks rec but not gap RECORD LOCKS space id 0 page no 343 n bits 144 index `PRIMARY` of table `test`.`table2_key_pk_parts_2_int_autoinc` /* Partition `p1` */ trx id AE4 lock_mode X locks rec but not gap TABLE LOCK table `test`.`table0_int_autoinc` trx id AE4 lock mode IX TABLE LOCK table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id AE4 lock mode IX RECORD LOCKS space id 0 page no 371 n bits 128 index `col_int_key` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id AE4 lock_mode X locks rec but not gap RECORD LOCKS space id 0 page no 368 n bits 120 index `PRIMARY` of table `test`.`table100_key_pk_parts_2_int_autoinc` /* Partition `p0` */ trx id AE4 lock_mode X locks rec but not gap TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS ---------------------------- END OF INNODB MONITOR OUTPUT ============================ WSREP: BF lock wait long

Nirbhay Choubey (Inactive) added a comment - 2014-10-04 04:35 Hi jplindst , I was able to reproduce it on 10.0-galera, but not on 5.5-galera. Also the patch which caused this regression was pushed only to wsrep-5.6 (and hence 10.0-galera).

Nirbhay Choubey (Inactive) added a comment - 2014-10-04 04:41 Pushed to maria-10.0-galera. http://bazaar.launchpad.net/~maria-captains/maria/maria-10.0-galera/revision/3898

Jan Lindström (Inactive) added a comment - 2014-10-04 13:32 Ok, same test does hang on 5.5.40-galera. This is serious, need to retest after merge with codership latests.

Michaël de groot added a comment - 2016-01-11 15:51 - edited Can we verify that this fix got added to the 5.5 tree as well?