Bug #88110 Error: semaphore wait has lasted > 600 seconds, and forcing recovery
Submitted: 16 Oct 2017 15:54 Modified: 16 Oct 2017 16:05
Reporter: wei xu Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Locking Severity:S2 (Serious)
Version:5.6.36-82 OS:CentOS (6.8 Final)
Assigned to: CPU Architecture:Any
Tags: crash, recovery, Semaphore, wait_ex

[16 Oct 2017 15:54] wei xu
Description:
=====================================
2017-10-15 23:42:13 7f58b13ff700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 4002570 srv_active, 0 srv_shutdown, 1941228 srv_idle
srv_master_thread log flush and writes: 5943798
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 37900623
--Thread 140018718861056 has waited at srv0srv.cc line 2651 for 935.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x13990c0 '&dict_operation_lock'
a writer (thread id 140018718861056) 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 770
Last time write locked in file /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.36-82.0/storage/innobase/srv/srv0srv.cc line 2651
--Thread 140018666411776 has waited at row0row.cc line 823 for 1031.0 seconds the semaphore:
X-lock on RW-latch at 0x7f610b69dda0 '&block->lock'
number of readers 0, waiters flag 0, lock_word: 100000
Last time read locked in file buf0flu.cc line 1078
Last time write locked in file /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.36-82.0/storage/innobase/row/row0row.cc line 823
wait has ended
--Thread 140018189850368 has waited at btr0cur.cc line 582 for 868.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f58b1c4df88 '&new_index->lock'
a writer (thread id 140018189850368) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.36-82.0/storage/innobase/btr/btr0cur.cc line 582
--Thread 140017992451840 has waited at btr0cur.cc line 591 for 868.00 seconds the semaphore:
S-lock on RW-latch at 0x7f58b1c4df88 '&new_index->lock'
a writer (thread id 140018189850368) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0cur.cc line 591
Last time write locked in file /mnt/workspace/percona-server-5.6-binaries-release/label_exp/centos6-64/percona-server-5.6.36-82.0/storage/innobase/btr/btr0cur.cc line 582

OS WAIT ARRAY INFO: signal count 36120306
Mutex spin waits 295671251, rounds 471268063, OS waits 1440878
RW-shared spins 50825783, rounds 1284526033, OS waits 35624829
RW-excl spins 4520550, rounds 58737253, OS waits 484195
Spin rounds per wait: 1.59 mutex, 25.27 RW-shared, 12.99 RW-excl

============================
END OF INNODB MONITOR OUTPUT
============================

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.
2017-10-15 23:42:32 7f58a4bfc700  InnoDB: Assertion failure in thread 140018697881344 in file srv0srv.cc line 2183
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.
15:42:32 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=262144
max_used_connections=4998
max_threads=100001
thread_count=4998
connection_count=4998
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 51286402 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 0x40000

/usr/local/Percona-Server-5.6.36/bin/mysqld(my_print_stacktrace+0x2c)[0x8fef3c]
/usr/local/Percona-Server-5.6.36/bin/mysqld(handle_fatal_signal+0x461)[0x680a41]
/lib64/libpthread.so.0[0x3a31a0f710]
/lib64/libc.so.6(gsignal+0x35)[0x3a31632625]
/lib64/libc.so.6(abort+0x175)[0x3a31633e05]

/usr/local/Percona-Server-5.6.36/bin/mysqld[0xa22b76]
/lib64/libpthread.so.0[0x3a31a079d1]
/lib64/libc.so.6(clone+0x6d)[0x3a316e89dd]

How to repeat:
Unknown
[16 Oct 2017 15:58] wei xu
may be duplicate of bug#73890
[16 Oct 2017 16:05] wei xu
not sure if duplicate with bug#73890:
1. lock wait at different files positions: btr0sea.c vs srv0srv.cc/row0row.cc/btr0cur.cc
2. some comment says bug#73890 is related to innodb_adaptive_hash_index option, but in this env innodb_adaptive_hash_index=0