Crash due to a long semaphore wait possibly due to deadlocked thread

Bug #1635768 reported by Ovais Tariq
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
New
Undecided
Unassigned

Bug Description

Percona Server version 5.6.30-76.3 though looking at 95c9a07c9037d27082d3d1d0800e6907a86a198b doesn't look like anything changed that should prevent the crash from happening in latest 5.6.

Crash message:
InnoDB: Warning: a long semaphore wait:
--Thread 139871293855488 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139858268354304 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139861602424576 has waited at btr0cur.cc line 591 for 570.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139859438765824 has waited at row0ins.cc line 1809 for 573.00 seconds the semaphore:
S-lock on RW-latch at 0x1362860 '&dict_operation_lock'
a writer (thread id 139874778728192) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0ins.cc line 1809
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/dict/dict0stats.cc line 2388
InnoDB: Warning: a long semaphore wait:
--Thread 139863352051456 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139873745737472 has waited at btr0cur.cc line 591 for 577.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139870322583296 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139870204339968 has waited at btr0cur.cc line 591 for 491.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139865210529536 has waited at btr0cur.cc line 591 for 559.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139861023811328 has waited at btr0cur.cc line 591 for 575.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139861385324288 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139874130208512 has waited at btr0cur.cc line 591 for 524.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139870693488384 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139862725093120 has waited at btr0cur.cc line 582 for 579.00 seconds the semaphore:
X-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139871155242752 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139873551193856 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139864820860672 has waited at btr0cur.cc line 257 for 547.00 seconds the semaphore:
S-lock on RW-latch at 0x7f4bce111800 '&block->lock'
a writer (thread id 139874223687424) 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 /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 257
InnoDB: Warning: a long semaphore wait:
--Thread 139873452336896 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139861270673152 has waited at btr0cur.cc line 582 for 579.00 seconds the semaphore:
X-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139871212357376 has waited at btr0cur.cc line 582 for 579.00 seconds the semaphore:
X-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139871405717248 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139873986377472 has waited at btr0cur.cc line 591 for 539.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371d05fd08 '&new_index->lock'
a writer (thread id 139861162825472) 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 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139873650853632 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139859164329728 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139865936545536 has waited at btr0cur.cc line 591 for 505.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139859259213568 has waited at btr0cur.cc line 591 for 571.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139859559778048 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139866848495360 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139873453340416 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139858268755712 has waited at btr0cur.cc line 591 for 566.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139859951073024 has waited at btr0cur.cc line 591 for 557.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139871698495232 has waited at row0ins.cc line 1809 for 559.00 seconds the semaphore:
S-lock on RW-latch at 0x1362860 '&dict_operation_lock'
a writer (thread id 139874778728192) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0ins.cc line 1809
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/dict/dict0stats.cc line 2388
InnoDB: Warning: a long semaphore wait:
--Thread 139872147707648 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139872416544512 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139864312948480 has waited at btr0cur.cc line 582 for 579.00 seconds the semaphore:
X-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139870898407168 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139861658355456 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139866427680512 has waited at btr0cur.cc line 257 for 550.00 seconds the semaphore:
X-lock on RW-latch at 0x7f4bce111560 '&block->lock'
a writer (thread id 139862270523136) 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 /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 257
InnoDB: Warning: a long semaphore wait:
--Thread 139874112628480 has waited at row0ins.cc line 1809 for 573.00 seconds the semaphore:
S-lock on RW-latch at 0x1362860 '&dict_operation_lock'
a writer (thread id 139874778728192) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0ins.cc line 1809
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/dict/dict0stats.cc line 2388
InnoDB: Warning: a long semaphore wait:
--Thread 139861764396800 has waited at btr0cur.cc line 591 for 572.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139866443032320 has waited at btr0cur.cc line 591 for 539.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
--Thread 139873990592256 has waited at row0undo.cc line 298 for 576.00 seconds the semaphore:
S-lock on RW-latch at 0x1362860 '&dict_operation_lock'
a writer (thread id 139874778728192) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0ins.cc line 1809
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/dict/dict0stats.cc line 2388
InnoDB: Warning: a long semaphore wait:
--Thread 139870968706816 has waited at btr0cur.cc line 591 for 529.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139871203587840 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139975452006144 has waited at btr0cur.cc line 591 for 570.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139861837707008 has waited at btr0cur.cc line 591 for 578.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139874213893888 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
--Thread 139862362175232 has waited at btr0cur.cc line 591 for 579.00 seconds the semaphore:
S-lock on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
InnoDB: Warning: a long semaphore wait:
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
2016-10-21 20:30:44 7f36ccfff700 InnoDB: Assertion failure in thread 139873344288512 in file srv0srv.cc line 2148
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.
20:30:44 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=16777216
read_buffer_size=131072
max_used_connections=16385
max_threads=16386
thread_count=16385
connection_count=16385
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6535565 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x8e71ec]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x66c3e1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xfcb0)[0x7f4e959c6cb0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7f4e94e1d035]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7f4e94e2079b]
/usr/sbin/mysqld[0x9d7096]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a)[0x7f4e959bee9a]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f4e94eda36d]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.

Locks:
41815 lock on RW-latch at 0x7f371e032508 '&new_index->lock'
 4875 lock on RW-latch at 0x7f371d05fd08 '&new_index->lock'
 3592 lock on RW-latch at 0x1362860 '&dict_operation_lock'
  973 lock on RW-latch at 0x7f460b71a8c0 '&block->lock'
  754 lock on RW-latch at 0x7f4327bd81c0 '&block->lock'
  676 lock on RW-latch at 0x7f4bcdd40d60 '&block->lock'
  472 lock on RW-latch at 0x7f4bce111800 '&block->lock'
  122 lock on RW-latch at 0x7f460fd80a60 '&block->lock'
  116 lock on RW-latch at 0x7f460f6f3460 '&block->lock'
   65 lock on RW-latch at 0x7f460f769660 '&block->lock'
   53 lock on RW-latch at 0x7f4bce111aa0 '&block->lock'
   37 lock on RW-latch at 0x7f460fd79440 '&block->lock'
   35 lock on RW-latch at 0x7f460f7fac20 '&block->lock'
   28 lock on RW-latch at 0x7f460fdb4540 '&block->lock'
   24 lock on RW-latch at 0x7f460fde1720 '&block->lock'
   23 lock on RW-latch at 0x7f460fcdc420 '&block->lock'
   19 lock on RW-latch at 0x7f4bce111560 '&block->lock'
   16 lock on RW-latch at 0x7f4bc5f4a5a0 '&block->lock'
   16 lock on RW-latch at 0x7f460f766720 '&block->lock'
   15 lock on RW-latch at 0x7f460fd7b900 '&block->lock'
   14 lock on RW-latch at 0x7f4329ec45e0 '&block->lock'
   12 lock on RW-latch at 0x7f460fd17520 '&block->lock'
   11 lock on RW-latch at 0x7f48eedc4fc0 '&block->lock'
    8 lock on RW-latch at 0x7f48ea578460 '&block->lock'
    6 lock on RW-latch at 0x7f460f783d00 '&block->lock'
    6 lock on RW-latch at 0x7f460f6f2f20 '&block->lock'
    4 lock on RW-latch at 0x7f48eedc1de0 '&block->lock'
    4 lock on RW-latch at 0x7f3a8edfb980 '&block->lock'
    3 lock on RW-latch at 0x7f460fde5b60 '&block->lock'
    2 lock on RW-latch at 0x7f460fd0cd20 '&block->lock'

Mutexes:
65328 Mutex at 0x7f373a800118 '&lock_sys->wait_mutex'
30151 Mutex at 0x7f373a800068 '&lock_sys->mutex'
    6 Mutex at 0x7f4e93e92068 '&trx_sys->mutex'
    3 Mutex at 0x134bc40 '&srv_innodb_monitor_mutex'

Waits at:
65004 lock0wait.cc line 223
45080 btr0cur.cc line 591
 9267 lock0lock.cc line 6149
 7433 lock0lock.cc line 4463
 7205 lock0lock.cc line 6941
 3902 lock0lock.cc line 6483
 2381 row0ins.cc line 2373
 2171 row0undo.cc line 298
 2014 lock0wait.cc line 271
 1656 btr0cur.cc line 582
 1400 row0ins.cc line 1809
 1199 btr0cur.cc line 257
  311 lock0wait.cc line 77
  274 lock0lock.cc line 6011
   33 row0ins.cc line 2718
   23 srv0srv.cc line 2653
   23 dict0stats.cc line 2388
   18 buf0flu.cc line 1078
   16 btr0cur.cc line 367
   13 lock0wait.cc line 510
   11 lock0lock.cc line 6294
   11 ha_innodb.cc line 4809
   10 lock0wait.cc line 95
   10 btr0pcur.cc line 431
    8 lock0lock.cc line 2797
    6 lock0lock.cc line 1248
    5 lock0lock.cc line 6402
    5 lock0lock.cc line 3516
    4 row0sel.cc line 3226
    3 read0read.ic line 117
    2 srv0srv.cc line 1632
    1 trx0trx.cc line 329
    1 trx0trx.cc line 1052
    1 srv0srv.cc line 1301
    1 lock0lock.cc line 6154

Last time write locked:

46736 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582
 3617 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/dict/dict0stats.cc line 2388
 2405 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/row/row0ins.cc line 2373
  668 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 257
  531 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/row/row0upd.cc line 2380
   29 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/row/row0ins.cc line 2718
   16 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 367
   12 Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/row/row0row.cc line 815

Revision history for this message
Ovais Tariq (ovais-tariq) wrote :

Analysis:
- thread id 139868969027328 has reserved &new_index->lock in mode wait exclusive
- all other threads are waiting on mtr_s_lock(dict_index_get_lock(index), mtr); which is a shared lock on the same index and is mutually exclusive with the wait exclusive lock

Appears to be a deadlock.

The thread 139868969027328 already has a wait_ex lock on index->lock.
Now its waiting for X-lock &new_index->lock

So what I understand is happening is:

thread 139868969027328 acquires a X lock &(index->lock)
thread 139868969027328 tries to acquire X lock &new_index->lock but the lock is already taken by itself.
Example:

--Thread 139868969027328 has waited at btr0cur.cc line 582 for 579.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f371e032508 '&new_index->lock'
a writer (thread id 139868969027328) has reserved it in mode wait exclusive
number of readers 42, waiters flag 1, lock_word: ffffffffffffffd6
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-debian-binary/label_exp/ubuntu-precise-64bit/percona-server-5.6-5.6.30-76.3/storage/innobase/btr/btr0cur.cc line 582

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Perhaps you have or can get the stacktraces of the server in the deadlocked state? Anything about the workload, configuration?

Revision history for this message
Ovais Tariq (ovais-tariq) wrote :

Laurynas, unfortunately I do not have the stack traces from the server in that state.

Here is the MySQL configuration:

#
# The MySQL database server configuration file.
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock

[mysqld_safe]

socket = /var/run/mysqld/mysqld.sock
nice = 0
numa_interleave = 1
flush_caches = 1
open_files_limit = 65536

[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
default-time-zone = '+0:00'
skip-external-locking
skip-name-resolve
read-only

performance_schema = 0
bind-address = 0.0.0.0

key_buffer = 16M
max_allowed_packet = 128M
thread_stack = 192K
thread_cache_size = 8

myisam-recover = BACKUP
max_connections = 16384

max_user_connections = 16374

query_cache_limit = 1M
query_cache_size = 16M

log-warnings = 2
log_error = /var/log/mysql/error.log

slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 10

log_slow_verbosity = microtime,innodb
slow_query_log_use_global_control = all

server-id = 935136378

log-bin = /var/lib/mysql/log/mysql-bin.log

auto_increment_increment = 2
auto_increment_offset = 1
relay-log = /var/lib/mysql/log/mysqld-relay-bin.log
enforce-gtid-consistency
gtid-mode = ON

sync_binlog = 1
log-slave-updates
expire_logs_days = 5
slave-net-time = 30
max_binlog_size = 1G
binlog_format = MIXED
table_definition_cache = 20000
table_open_cache_instances = 20000
lock_wait_timeout = 300

relay_log_info_repository = TABLE
relay_log_recovery = ON

default-storage-engine = innodb

innodb_buffer_pool_size = 94561221214
innodb_flush_method = O_DIRECT
innodb_file_per_table
innodb_log_file_size = 512M
innodb_file_format = ANTELOPE
innodb_flush_log_at_trx_commit = 1
innodb_kill_idle_transaction = 0

character-set-server=utf8mb4
collation-server=utf8mb4_unicode_ci

[mysqldump]
quick
quote-names
max_allowed_packet = 16M
single-transaction

[mysql]
#no-auto-rehash # faster start of mysql but no tab completition

[isamchk]
key_buffer = 16M

#
# * IMPORTANT: Additional settings that can override those from this file!
# The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/

The workload is 99% reads, 1% writes. Majority of the data is stored in blob columns. Majority of the writes are INSERTs

Revision history for this message
Ovais Tariq (ovais-tariq) wrote :

Let me know if you need any more information from me.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3583

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.