[MDEV-8869] Potential lock_sys->mutex deadlock Created: 2015-09-29  Updated: 2018-02-27  Resolved: 2015-12-21

Status: Closed
Project: MariaDB Server
Component/s: Galera, Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0.19-galera
Fix Version/s: 10.1.10, 10.0.23-galera

Type: Bug Priority: Blocker
Reporter: Geoff Montee (Inactive) Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: galera

Issue Links:
Duplicate
is duplicated by MDEV-9192 Bug MDEV-8869 still present with Mari... Closed
Relates
relates to MDEV-15431 lock_sys->mutex happened Closed
Sprint: 10.0.23

 Description   

Some users have noticed that under certain workloads, MariaDB Galera Cluster 10.0.19 consistently hangs. The only way to unhang the server at that point is to kill the process.

I'm going to ask the users to confirm that this issue is still present on MariaDB Galera Cluster 10.0.21 as well.

The users' logs seem to suggest there might be a deadlock related to lock_sys->mutex. An excerpt of the log is here:

InnoDB: Warning: a long semaphore wait:
 
--Thread 140725687342848 has waited at ha_innodb.cc line 4970 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140688432944896 has waited at lock0lock.cc line 7545 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140688439523072 has waited at btr0cur.cc line 257 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7ff7f9da5dc0 '&block->lock'
 
a writer (thread id 140725687342848) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file btr0cur.cc line 257
 
Last time write locked in file /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc line 257
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140688437131008 has waited at lock0lock.cc line 6602 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140688439224064 has waited at btr0cur.cc line 257 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7ff7f9da5940 '&block->lock'
 
a writer (thread id 140688437131008) 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 3222
 
Last time write locked in file /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc line 257
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725683754752 has waited at lock0lock.cc line 7545 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726214985472 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726349707008 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726216181504 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726214686464 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725684352768 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725685249792 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725685847808 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726215583488 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725686146816 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726214387456 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726216480512 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726216779520 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725686744832 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726217377536 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725686445824 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725684950784 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726215882496 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140725687043840 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140726215284480 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: a long semaphore wait:
 
--Thread 140688451208960 has waited at buf0flu.cc line 1079 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7ff7f9da5940 '&block->lock'
 
a writer (thread id 140688437131008) 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 3222
 
Last time write locked in file /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc line 257
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725687342848 has waited at ha_innodb.cc line 4970 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140688432944896 has waited at lock0lock.cc line 7545 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140688439523072 has waited at btr0cur.cc line 257 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7ff7f9da5dc0 '&block->lock'
 
a writer (thread id 140725687342848) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file btr0cur.cc line 257
 
Last time write locked in file /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc line 257
 
InnoDB: Warning: Writer thread is waiting this semaphore:
 
--Thread 140725687342848 has waited at ha_innodb.cc line 4970 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140688437131008 has waited at lock0lock.cc line 6602 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140688439224064 has waited at btr0cur.cc line 257 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7ff7f9da5940 '&block->lock'
 
a writer (thread id 140688437131008) 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 3222
 
Last time write locked in file /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc line 257
 
InnoDB: Warning: Writer thread is waiting this semaphore:
 
--Thread 140688437131008 has waited at lock0lock.cc line 6602 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725683754752 has waited at lock0lock.cc line 7545 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726214985472 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726349707008 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726216181504 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726214686464 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725684352768 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725685249792 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725685847808 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726215583488 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725686146816 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726214387456 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726216480512 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726216779520 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725686744832 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726217377536 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725686445824 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725684950784 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726215882496 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725687043840 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140726215284480 has waited at lock0lock.cc line 5011 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140688451208960 has waited at buf0flu.cc line 1079 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7ff7f9da5940 '&block->lock'
 
a writer (thread id 140688437131008) 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 3222
 
Last time write locked in file /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc line 257
 
InnoDB: Warning: Writer thread is waiting this semaphore:
 
--Thread 140688437131008 has waited at lock0lock.cc line 6602 for 241.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140688436233984 has waited at lock0lock.cc line 5011 for 234.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725680166656 has waited at lock0lock.cc line 5011 for 232.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725678970624 has waited at lock0lock.cc line 5011 for 222.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725683156736 has waited at lock0lock.cc line 5011 for 218.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1
 
InnoDB: Warning: semaphore wait:
 
--Thread 140725682558720 has waited at lock0lock.cc line 5011 for 197.00 seconds the semaphore:
 
Mutex at 0x3a69d468 '&lock_sys->mutex', lock var 1
 
waiters flag 1

This might be related to these PXC bugs:

https://bugs.launchpad.net/percona-xtradb-cluster/5.6/+bug/1233301

https://bugs.launchpad.net/percona-server/+bug/1233690

https://bugs.launchpad.net/percona-xtradb-cluster/5.6/+bug/1231518

The users' stack trace does show one thread grabbing the mutex in innobase_kill_connection, which is where PXC's bug report mention the issue happening. The user's stack trace:

Thread 59 (Thread 0x7f7b18771700 (LWP 16521)):
 
#0  0x0000003fa180b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /usr/local/mariadb/mariadb_base/lib64/libpthread.so.0
 
#1  0x00000000009865e7 in os_cond_wait (event=0x3bc5df50, reset_sig_count=25114) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/os/os0syn
 
c.cc:214
 
#2  os_event_wait_low (event=0x3bc5df50, reset_sig_count=25114) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/os/os0sync.cc:610
 
#3  0x00000000009ebe7a in sync_array_wait_event (arr=0x3999ae0, index=1) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/sync/sync0arr.cc:
 
461
 
#4  0x00000000009ed813 in mutex_spin_wait (_mutex=0x3bade118, high_priority=false, file_name=0xc7a288 "/buildroot/mariadb/mariadb-10.0.19/stora
 
ge/xtradb/handler/ha_innodb.cc", line=4970) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/sync/sync0sync.cc:686
 
#5  0x00000000009371d6 in pfs_mutex_enter_func (hton=<value optimized out>, thd=<value optimized out>) at /buildroot/mariadb/mariadb-10.0.19/st
 
orage/xtradb/include/sync0sync.ic:274
 
#6  innobase_kill_connection (hton=<value optimized out>, thd=<value optimized out>) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/handl
 
er/ha_innodb.cc:4970
 
#7  0x0000000000702c04 in kill_handlerton (thd=0x3bf54608, plugin=<value optimized out>, level=0x7f7b1876c9b4) at /buildroot/mariadb/mariadb-10
 
.0.19/sql/handler.cc:791
 
#8  0x00000000005a0812 in plugin_foreach_with_mask (thd=0x3bf54608, func=0x702bc0 <kill_handlerton(THD*, plugin_ref, void*)>, type=10, state_mask=<val
 
ue optimized out>, arg=0x7f7b1876c9b4) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_plugin.cc:2340
 
#9  0x0000000000701701 in ha_kill_query (thd=0x3bc5df94, level=THD_ABORT_SOFTLY) at /buildroot/mariadb/mariadb-10.0.19/sql/handler.cc:798
 
#10 0x000000000056c8a7 in THD::awake (this=0x3bf54608, state_to_set=KILL_QUERY) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_class.cc:2015
 
#11 0x000000000056ca6f in wsrep_thd_awake (thd=0x3bf54608, signal=<value optimized out>) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_class.cc
 
:952
 
#12 0x0000000000934434 in wsrep_innobase_kill_one_trx (bf_thd_ptr=0x0, bf_trx=0x7f722001b9a8, victim_trx=0x7f713c0f0398, signal=1) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/handler/ha_innodb.cc:18440
 
#13 0x0000000000960dd1 in lock_rec_other_has_conflicting (mode=<value optimized out>, block=<value optimized out>, heap_no=13, trx=0x7f722001b9a8) at
 
/buildroot/mariadb/mariadb-10.0.19/storage/xtradb/lock/lock0lock.cc:1766
 
#14 0x000000000096904f in lock_rec_insert_check_and_lock (flags=<value optimized out>, rec=<value optimized out>, block=0x7f75c3a0cf80, index=0x7f7254
 
022028, thr=0x7f71583775a8, mtr=0x7f7b1876d1b0, inherit=0x7f7b1876d0e8) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/lock/lock0lock.cc:
 
6644
 
#15 0x0000000000a266b3 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7f7b1876d740, offsets=0x7f7b1876d838, heap=0x7f7b1876d1a8, entry=0x7f7178339b78
 
, rec=0x7f7b1876d830, big_rec=0x7f7b1876d820, n_ext=0, thr=0x7f71583775a8, mtr=0x7f7b1876d1b0) at /buildroot/mariadb/mariadb-10.0.19/storage/xt
 
radb/btr/btr0cur.cc:1263
 
#16 btr_cur_optimistic_insert (flags=0, cursor=0x7f7b1876d740, offsets=0x7f7b1876d838, heap=0x7f7b1876d1a8, entry=0x7f7178339b78, rec=0x7f7b1876d830,
 
big_rec=0x7f7b1876d820, n_ext=0, thr=0x7f71583775a8, mtr=0x7f7b1876d1b0) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/btr/btr0cur.cc:15
 
01
 
#17 0x00000000009b11f3 in row_ins_sec_index_entry_low (flags=0, mode=2, index=0x7f7254022028, offsets_heap=0x7f7220598fb0, heap=0x7f7220599420, entry=
 
0x7f7178339b78, trx_id=0, thr=0x7f71583775a8) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/row/row0ins.cc:2802
 
#18 0x00000000009b3981 in row_ins_sec_index_entry (index=0x7f7254022028, entry=0x7f7178339b78, thr=0x7f71583775a8) at /buildroot/mariadb/mariad
 
b-10.0.19/storage/xtradb/row/row0ins.cc:2987
 
#19 0x00000000009b5173 in row_ins (thr=0x7f71583775a8) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/row/row0ins.cc:3026
 
#20 row_ins_step (thr=0x7f71583775a8) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/row/row0ins.cc:3366
 
#21 0x00000000009be000 in row_insert_for_mysql (mysql_rec=<value optimized out>, prebuilt=0x7f7158376878) at /buildroot/mariadb/mariadb-10.0.19
 
/storage/xtradb/row/row0mysql.cc:1369
 
#22 0x000000000093c873 in ha_innobase::write_row (this=0x7f7158441f30, record=0x7f71582ea7d0 "¦Q\026¦\"") at /buildroot/mariadb/mariadb-10.0.19
 
/storage/xtradb/handler/ha_innodb.cc:8189
 
#23 0x0000000000707330 in handler::ha_write_row (this=0x7f7158441f30, buf=0x7f71582ea7d0 "¦Q\026¦\"") at /buildroot/mariadb/mariadb-10.0.19/sql
 
/handler.cc:6050
 
#24 0x00000000007c8bc6 in Rows_log_event::write_row (this=0x7f7220598518, rgi=0x7f7220015f90, overwrite=false) at /buildroot/mariadb/mariadb-10
 
.0.19/sql/log_event.cc:11464
 
#25 0x00000000007c8f28 in Write_rows_log_event::do_exec_row (this=0x7f7220598518, rgi=0x7f7220015f90) at /buildroot/mariadb/mariadb-10.0.19/sql
 
/log_event.cc:11658
 
#26 0x00000000007ceda5 in Rows_log_event::do_apply_event (this=0x7f7220598518, rgi=0x7f7220015f90) at /buildroot/mariadb/mariadb-10.0.19/sql/lo
 
g_event.cc:9925
 
#27 0x00000000006ae59c in apply_event (ctx=0x7f7220000998, buf=0x7f7bd1a12905, buf_len=466, flags=<value optimized out>, meta=<value optimized out>) a
 
t /buildroot/mariadb/mariadb-10.0.19/sql/log_event.h:1343
 
#28 wsrep_apply_events (ctx=0x7f7220000998, buf=0x7f7bd1a12905, buf_len=466, flags=<value optimized out>, meta=<value optimized out>) at /buildroot/mariadb/mariadb-10.0.19/sql/wsrep_applier.cc:169
 
#29 wsrep_apply_cb (ctx=0x7f7220000998, buf=0x7f7bd1a12905, buf_len=466, flags=<value optimized out>, meta=<value optimized out>) at /buildroot
 
/mariadb/mariadb-10.0.19/sql/wsrep_applier.cc:256
 
#30 0x00007f7c7a9a29f3 in ?? ()
 
#31 0x00007f71e00214d0 in ?? ()
 
#32 0x0000000000000003 in ?? ()
 
#33 0x0000000003992e30 in ?? ()
 
#34 0x00007f71e00214d0 in ?? ()
 
#35 0x0000000000000000 in ?? ()

This could also be related to this Codership bug:

https://github.com/codership/mysql-wsrep/issues/184

However, I'm not sure if that bug can lead to deadlocks specific to lock_sys->mutex.

The user's stack trace shows one thread that is similar to the thread 41 in that issue. The user's stack trace:

Thread 28 (Thread 0x7f725a046700 (LWP 27356)):
 
#0  0x0000003fa180b5bc in pthread_cond_wait@@GLIBC_2.3.2 () from /usr/local/mariadb/mariadb_base/lib64/libpthread.so.0
 
#1  0x00000000009865e7 in os_cond_wait (event=0x3bc5df50, reset_sig_count=25114) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/os/os0syn
 
c.cc:214
 
#2  os_event_wait_low (event=0x3bc5df50, reset_sig_count=25114) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/os/os0sync.cc:610
 
#3  0x00000000009ebe7a in sync_array_wait_event (arr=0x3999ae0, index=3) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/sync/sync0arr.cc:
 
461
 
#4  0x00000000009ed813 in mutex_spin_wait (_mutex=0x3bade118, high_priority=false, file_name=0xc84d58 "/buildroot/mariadb/mariadb-10.0.19/stora
 
ge/xtradb/lock/lock0lock.cc", line=7545) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/sync/sync0sync.cc:686
 
#5  0x0000000000964fb6 in mutex_enter_func (trx=0x7f715c007d88) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/include/sync0sync.ic:274
 
#6  pfs_mutex_enter_func (trx=0x7f715c007d88) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/include/sync0sync.ic:369
 
#7  lock_trx_release_locks (trx=0x7f715c007d88) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/lock/lock0lock.cc:7545
 
#8  0x0000000000a01ebe in trx_commit_in_memory (trx=0x7f715c007d88, mtr=0x0) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/trx/trx0trx.c
 
c:1423
 
#9  trx_commit_low (trx=0x7f715c007d88, mtr=0x0) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/trx/trx0trx.cc:1643
 
#10 0x0000000000a0271a in trx_commit (trx=0x3bc5df94) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/trx/trx0trx.cc:1664
 
#11 0x0000000000a03043 in trx_commit_for_mysql (trx=0x7f715c007d88) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/trx/trx0trx.cc:1928
 
#12 0x000000000092c0aa in innobase_commit_low (trx=0x7f715c007d88) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/handler/ha_innodb.cc:40
 
71
 
#13 0x0000000000935b2f in innobase_commit_ordered_2 (trx=0x7f715c007d88, thd=0x3bf0be88) at /buildroot/mariadb/mariadb-10.0.19/storage/xtradb/h
 
andler/ha_innodb.cc:4183
 
#14 0x000000000093c643 in innobase_commit (hton=0x39f3918, thd=0x3bf0be88, commit_trx=true) at /buildroot/mariadb/mariadb-10.0.19/storage/xtrad
 
b/handler/ha_innodb.cc:4407
 
#15 0x0000000000704fb7 in commit_one_phase_2 (thd=0x3bf0be88, all=true, trans=0x3bf0edd8, is_real_trans=true) at /buildroot/mariadb/mariadb-10.
 
0.19/sql/handler.cc:1585
 
#16 0x000000000070540c in ha_commit_trans (thd=0x3bf0be88, all=true) at /buildroot/mariadb/mariadb-10.0.19/sql/handler.cc:1405
 
#17 0x00000000006621b4 in trans_commit (thd=0x3bf0be88) at /buildroot/mariadb/mariadb-10.0.19/sql/transaction.cc:239
 
#18 0x0000000000591bf8 in mysql_execute_command (thd=0x3bf0be88) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_parse.cc:4830
 
#19 0x00000000005978ea in mysql_parse (thd=0x3bf0be88, rawbuf=0x7f715c004ce0 "COMMIT", length=<value optimized out>, parser_state=0x7f725a045650) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_parse.cc:7154
 
#20 0x000000000059794e in wsrep_mysql_parse (thd=0x3bf0be88, rawbuf=0x7f715c004ce0 "COMMIT", length=6, parser_state=0x7f725a045650) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_parse.cc:6976
 
#21 0x0000000000599ce0 in dispatch_command (command=COM_QUERY, thd=0x3bf0be88, packet=0x3bf10f5d "COMMIT", packet_length=6) at /buildroot/maria
 
db/mariadb-10.0.19/sql/sql_parse.cc:1487
 
#22 0x000000000059a675 in do_command (thd=0x3bf0be88) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_parse.cc:1083
 
#23 0x00000000006537f9 in do_handle_one_connection (thd_arg=0x3bf0be88) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_connect.cc:1392
 
#24 0x00000000006539d0 in handle_one_connection (arg=0x3bf0be88) at /buildroot/mariadb/mariadb-10.0.19/sql/sql_connect.cc:1303
 
#25 0x0000003fa18079d1 in start_thread () from /usr/local/mariadb/mariadb_base/lib64/libpthread.so.0
 
#26 0x0000003fa14e88fd in clone () from /usr/local/mariadb/mariadb_base/lib64/libc.so.6



 Comments   
Comment by Elena Stepanova [ 2015-09-29 ]

nirbhay_c, if it turns out to be unrelated to Galera, please feel free to reassign.

Comment by Jan Lindström (Inactive) [ 2015-10-14 ]

Confirmed, bug on Galera environment.

Comment by Jan Lindström (Inactive) [ 2015-10-21 ]

commit 17b0b45b1de41a1b188c5de6c3e9d8e6ecc48a72
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Oct 21 09:20:54 2015 +0300

Code cleanup.

commit f3e362464bb67c02236a2ecb7526fb0c046e8474
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Tue Oct 20 13:41:14 2015 +0300

MDEV-8869: Potential lock_sys->mutex deadlock

Analysis: We are alreading holing lock_sys mutex when we call thd::awake.
This could lead mutex deadlock if trx->current_lock_mutex_owner is not
correctly set.

Fix: Make sure that trx->current_lock_mutex_owner is correctly set.

Comment by Jan Lindström (Inactive) [ 2015-12-08 ]

Customer had new lockup.

Comment by Jan Lindström (Inactive) [ 2015-12-14 ]

commit 4437f51682b22caaf2cf0b00de1bf6fa3edf6557
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Mon Dec 14 10:10:09 2015 +0200

MDEV-8869: Potential lock_sys->mutex deadlock

In wsrep brute force (BF) we have already took lock_sys and trx
mutex either on wsrep_abort_transaction() or
before wsrep_kill_victim().

Comment by Nirbhay Choubey (Inactive) [ 2015-12-20 ]

The last commit seemingly has broken the kill mechanism.

https://github.com/MariaDB/server/commit/4437f51682b22caaf2cf0b00de1bf6fa3edf6557

Failing test(s): rpl.rpl_parallel rpl.rpl_parallel_retry rpl.rpl_parallel_no_log_slave_updates main.innodb_mysql_sync main.flush_read_lock main.flush_read_lock_kill main.show_explain

151219 16:45:28 [ERROR] mysqld got signal 11 ;
 
..skip..
 
Server version: 10.0.23-MariaDB-wsrep-debug-log
 
..skip..
 
stack_bottom = 0x7faf8c886df0 thread_stack 0x48000
 
mysys/stacktrace.c:246(my_print_stacktrace)[0xe946f5]
 
sql/signal_handler.cc:155(handle_fatal_signal)[0x87715c]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7faf8bc90340]
 
lock/lock0lock.cc:7471(lock_cancel_waiting_and_release(ib_lock_t*))[0xc15895]
 
handler/ha_innodb.cc:5059(innobase_kill_connection)[0xbad02f]
 
sql/handler.cc:792(kill_handlerton)[0x879944]
 
sql/sql_plugin.cc:2332(plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int**, void*), int, unsigned int, void*))[0x672476]
 
sql/handler.cc:799(ha_kill_query(THD*, thd_kill_levels))[0x87999d]
 
sql/sql_class.cc:2028(THD::awake(killed_state))[0x61a1af]
 
sql/sql_parse.cc:8147(kill_one_thread(THD*, long long, killed_state, killed_type))[0x667a70]
 
sql/sql_parse.cc:8251(sql_kill)[0x667ecf]
 
sql/sql_parse.cc:4777(mysql_execute_command(THD*))[0x65ed28]
 
sql/sql_parse.cc:7203(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x665ac1]
 
sql/sql_parse.cc:7026(wsrep_mysql_parse)[0x66520d]
 
sql/sql_parse.cc:1487(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x6556cf]
 
sql/sql_parse.cc:1093(do_command(THD*))[0x65439e]
 
sql/sql_connect.cc:1394(do_handle_one_connection(THD*))[0x78332b]
 
sql/sql_connect.cc:1307(handle_one_connection)[0x78308f]
 
perfschema/pfs.cc:1862(pfs_spawn_thread)[0xb8f2b6]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7faf8bc88182]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7faf8ab6d47d]
 

2015-12-19 16:46:01 7fa95c53a700  InnoDB: Assertion failure in thread 140365375186688 in file ha_innodb.cc line 5048
 
InnoDB: Failing assertion: !mutex_own(&lock_sys->mutex)
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
151219 16:46:01 [ERROR] mysqld got signal 6 ;
 
..skip..
 
stack_bottom = 0x7fa95c539d80 thread_stack 0x48000
 
mysys/stacktrace.c:246(my_print_stacktrace)[0xe946f5]
 
sql/signal_handler.cc:155(handle_fatal_signal)[0x87715c]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7fa95d96e340]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x39)[0x7fa95c787cc9]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7fa95c78b0d8]
 
handler/ha_innodb.cc:5049(innobase_kill_connection)[0xbacf3b]
 
sql/handler.cc:792(kill_handlerton)[0x879944]
 
sql/sql_plugin.cc:2332(plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int**, void*), int, unsigned int, void*))[0x672476]
 
sql/handler.cc:799(ha_kill_query(THD*, thd_kill_levels))[0x87999d]
 
sql/sql_class.cc:2028(THD::awake(killed_state))[0x61a1af]
 
sql/sql_class.cc:4594(thd_report_wait_for)[0x6214e4]
 
lock/lock0lock.cc:4431(lock_report_waiters_to_mysql)[0xc0e2cd]
 
lock/lock0lock.cc:4501(lock_deadlock_check_and_resolve)[0xc0e5da]
 
lock/lock0lock.cc:2270(lock_rec_enqueue_waiting)[0xc09bad]
 
lock/lock0lock.cc:6664(lock_rec_insert_check_and_lock(unsigned long, unsigned char const*, buf_block_t*, dict_index_t*, que_thr_t*, mtr_t*, unsigned long*))[0xc13c5a]
 
btr/btr0cur.cc:1268(btr_cur_ins_lock_and_undo)[0xd6c6cf]
 
btr/btr0cur.cc:1503(btr_cur_optimistic_insert(unsigned long, btr_cur_t*, unsigned long**, mem_block_info_t**, dtuple_t*, unsigned char**, big_rec_t**, unsigned long, que_thr_t*, mtr_t*))[0xd6cdfa]
 
row/row0ins.cc:2857(row_ins_sec_index_entry_low(unsigned long, unsigned long, dict_index_t*, mem_block_info_t*, mem_block_info_t*, dtuple_t*, unsigned long, que_thr_t*))[0xc9bc1d]
 
row/row0ins.cc:3042(row_ins_sec_index_entry(dict_index_t*, dtuple_t*, que_thr_t*))[0xc9c385]
 
row/row0upd.cc:2041(row_upd_sec_index_entry)[0xcf05f9]
 
row/row0upd.cc:2068(row_upd_sec_step)[0xcf0736]
 
row/row0upd.cc:2877(row_upd)[0xcf2349]
 
row/row0upd.cc:2994(row_upd_step(que_thr_t*))[0xcf262b]
 
row/row0mysql.cc:1797(row_update_for_mysql(unsigned char*, row_prebuilt_t*))[0xcb4c60]
 
handler/ha_innodb.cc:8884(ha_innobase::update_row(unsigned char const*, unsigned char*))[0xbb45dd]
 
sql/handler.cc:6124(handler::ha_update_row(unsigned char const*, unsigned char*))[0x8852a1]
 
sql/sql_update.cc:816(mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, enum_duplicates, bool, unsigned long long*, unsigned long long*))[0x72e08e]
 
sql/sql_parse.cc:3641(mysql_execute_command(THD*))[0x65abfd]
 
sql/sql_parse.cc:7203(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x665ac1]
 
sql/log_event.cc:4364(Query_log_event::do_apply_event(rpl_group_info*, char const*, unsigned int))[0x96abca]
 
sql/log_event.cc:4052(Query_log_event::do_apply_event(rpl_group_info*))[0x969cbb]
 
sql/log_event.h:1361(Log_event::apply_event(rpl_group_info*))[0x5c5a6a]
 
sql/slave.cc:3298(apply_event_and_update_pos(Log_event*, THD*, rpl_group_info*, rpl_parallel_thread*))[0x5bb426]
 
sql/rpl_parallel.cc:52(rpt_handle_event)[0x7e72c8]
 
sql/rpl_parallel.cc:1201(handle_rpl_parallel_thread)[0x7e9df8]
 
perfschema/pfs.cc:1862(pfs_spawn_thread)[0xb8f2b6]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7fa95d966182]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fa95c84b47d]

Comment by Jan Lindström (Inactive) [ 2015-12-21 ]

commit 080da551ea171f8a43633ab27b56875938643dd0
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Mon Dec 21 16:36:26 2015 +0200

MDEV-8869: Potential lock_sys->mutex deadlock

In wsrep BF we have already took lock_sys and trx
mutex either on wsrep_abort_transaction() or
before wsrep_kill_victim(). In replication we
could own lock_sys mutex taken in
lock_deadlock_check_and_resolve().

Generated at Thu Feb 08 07:30:23 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.