Lock deadlock with PXC 5.6

Bug #1231518 reported by Raghavendra D Prabhu
This bug report is a duplicate of:  Bug #1233301: Deadlock with wsrep_kill_victim. Edit Remove
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
5.6
New
Undecided
Unassigned

Bug Description

===================================================================

2013-09-26 17:51:53 16072 [Note] WSREP: Member 1 (jhc-new-3-centos6-64) synced with group.
InnoDB: Warning: a long semaphore wait:
--Thread 139810324395776 has waited at ha_innodb.cc line 4309 for 241.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810323064576 has waited at lock0lock.cc line 4708 for 241.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810322798336 has waited at lock0lock.cc line 4708 for 241.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810323330816 has waited at lock0lock.cc line 4708 for 241.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810077374208 has waited at lock0lock.cc line 3636 for 241.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2013-09-26 17:56:17 7f2816ffb700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 8 srv_active, 0 srv_shutdown, 20 srv_idle
srv_master_thread log flush and writes: 27
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 103
--Thread 139810324395776 has waited at ha_innodb.cc line 4309 for 253.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810323064576 has waited at lock0lock.cc line 4708 for 253.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810322798336 has waited at lock0lock.cc line 4708 for 253.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810323330816 has waited at lock0lock.cc line 4708 for 253.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810077374208 has waited at lock0lock.cc line 3636 for 253.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810056398592 has waited at buf0flu.cc line 1052 for 252.00 seconds the semaphore:
S-lock on RW-latch at 0x7f28235fa9c0 '&block->lock'
a writer (thread id 139810077374208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3232
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/row/row0row.cc line 815
--Thread 139810098349824 has waited at srv0srv.cc line 2541 for 252.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x1364780 '&dict_operation_lock'
a writer (thread id 139810098349824) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file row0purge.cc line 720
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/srv/srv0srv.cc line 2541
OS WAIT ARRAY INFO: signal count 95
Mutex spin waits 169, rounds 3223, OS waits 72
RW-shared spins 46, rounds 1211, OS waits 16
RW-excl spins 3, rounds 461, OS waits 14
Spin rounds per wait: 19.07 mutex, 26.33 RW-shared, 153.67 RW-excl
FAIL TO OBTAIN LOCK MUTEX, SKIP LOCK INFO PRINTING
--------
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 (write thread)
I/O thread 5 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0] , aio writes: 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
596 OS file reads, 3257 OS file writes, 1957 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
0.00 hash searches/s, 0.00 non-hash searches/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 139810324395776 has waited at ha_innodb.cc line 4309 for 272.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810323064576 has waited at lock0lock.cc line 4708 for 272.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810322798336 has waited at lock0lock.cc line 4708 for 272.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810323330816 has waited at lock0lock.cc line 4708 for 272.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810077374208 has waited at lock0lock.cc line 3636 for 272.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810056398592 has waited at buf0flu.cc line 1052 for 271.00 seconds the semaphore:
S-lock on RW-latch at 0x7f28235fa9c0 '&block->lock'
a writer (thread id 139810077374208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3232
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/row/row0row.cc line 815
InnoDB: Warning: a long semaphore wait:
--Thread 139810098349824 has waited at srv0srv.cc line 2541 for 271.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x1364780 '&dict_operation_lock'
a writer (thread id 139810098349824) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file row0purge.cc line 720
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/srv/srv0srv.cc line 2541
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2013-09-26 17:56:37 7f2816ffb700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 8 srv_active, 0 srv_shutdown, 20 srv_idle
srv_master_thread log flush and writes: 27
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 103
--Thread 139810324395776 has waited at ha_innodb.cc line 4309 for 273.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810323064576 has waited at lock0lock.cc line 4708 for 273.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810322798336 has waited at lock0lock.cc line 4708 for 273.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810323330816 has waited at lock0lock.cc line 4708 for 273.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810077374208 has waited at lock0lock.cc line 3636 for 273.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810056398592 has waited at buf0flu.cc line 1052 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0x7f28235fa9c0 '&block->lock'
a writer (thread id 139810077374208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3232
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/row/row0row.cc line 815
--Thread 139810098349824 has waited at srv0srv.cc line 2541 for 272.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x1364780 '&dict_operation_lock'
a writer (thread id 139810098349824) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file row0purge.cc line 720
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/srv/srv0srv.cc line 2541
OS WAIT ARRAY INFO: signal count 95
Mutex spin waits 169, rounds 3223, OS waits 72
RW-shared spins 46, rounds 1211, OS waits 16
RW-excl spins 3, rounds 461, OS waits 14
Spin rounds per wait: 19.07 mutex, 26.33 RW-shared, 153.67 RW-excl
FAIL TO OBTAIN LOCK MUTEX, SKIP LOCK INFO PRINTING
----------
OS WAIT ARRAY INFO: reservation count 103
--Thread 139810324395776 has waited at ha_innodb.cc line 4309 for 293.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810323064576 has waited at lock0lock.cc line 4708 for 293.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810322798336 has waited at lock0lock.cc line 4708 for 293.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810323330816 has waited at lock0lock.cc line 4708 for 293.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810077374208 has waited at lock0lock.cc line 3636 for 293.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
--Thread 139810056398592 has waited at buf0flu.cc line 1052 for 292.00 seconds the semaphore:
S-lock on RW-latch at 0x7f28235fa9c0 '&block->lock'
a writer (thread id 139810077374208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3232
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/row/row0row.cc line 815
--Thread 139810098349824 has waited at srv0srv.cc line 2541 for 292.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x1364780 '&dict_operation_lock'
a writer (thread id 139810098349824) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file row0purge.cc line 720
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/srv/srv0srv.cc line 2541
OS WAIT ARRAY INFO: signal count 95
Mutex spin waits 169, rounds 3223, OS waits 72
RW-shared spins 46, rounds 1211, OS waits 16
RW-excl spins 3, rounds 461, OS waits 14
Spin rounds per wait: 19.07 mutex, 26.33 RW-shared, 153.67 RW-excl
FAIL TO OBTAIN LOCK MUTEX, SKIP LOCK INFO PRINTING
--------
FILE I/O
FAIL TO OBTAIN LOCK MUTEX, SKIP LOCK INFO PRINTING
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 139810324395776 has waited at ha_innodb.cc line 4309 for 303.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810323064576 has waited at lock0lock.cc line 4708 for 303.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810322798336 has waited at lock0lock.cc line 4708 for 303.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810323330816 has waited at lock0lock.cc line 4708 for 303.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810077374208 has waited at lock0lock.cc line 3636 for 303.00 seconds the semaphore:
Mutex at 0x7f282340b088 '&lock_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139810056398592 has waited at buf0flu.cc line 1052 for 302.00 seconds the semaphore:
S-lock on RW-latch at 0x7f28235fa9c0 '&block->lock'
a writer (thread id 139810077374208) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.cc line 3232
Last time write locked in file /mnt/workspace/build-xtradb-cluster-binaries-56/BUILD_TYPE/release/label_exp/centos6-64/Percona-XtraDB-Cluster-5.6.13/storage/innobase/row/row0row.cc line 815

==========================================================

Full details here http://jenkins.percona.com/job/PXC-5.6-msysbench/BTYPE=release,Host=centos6-64/ws/12/mysqldir/node1/log/mysqld.1.err/*view*/

no longer affects: percona-xtradb-cluster
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Attached backtrace.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Bug attachments