Long semaphore wait crashes PS 5.7
| Affects | Status | Importance | Assigned to | Milestone | |
|---|---|---|---|---|---|
| Percona Server moved to https://jira.percona.com/projects/PS |
New
|
Undecided
|
Unassigned | ||
Bug Description
Occasionally a thread doing purge operation for undo log can stuck in deadlock and then blocks other threads because the thread holds the data dictionary lock. After 600 seconds, MySQL intentionally crashes.
I managed to capture "show engine innodb status" output and stack trace using GDB (see below). I am not very familiar with MySQL source code. Here is my rudimentary analysis (which could be wrong):
Thread 140039501625088 is stuck. The thread is trying to acquire an x-lock on a buffer pool page whose s-lock and sx-lock are already acquired by it. Lockword: ffffffffefffffff means "S locked, with a waiting writer which has SX lock. The number of S lock is 1.". Thread 140039501625088 holds the data dictionary lock while being stuck, so other threads are blocked.
s-lock is acquired when the thread is searching undo record in a secondary index.
sx-lock is acquired when the thread is either searching undo record or doing recursive merge for B-Tree nodes.
x-lock is being acquired when the thread is doing recursive merge of B-Tree nodes.
I thought the thread would upgrade the s-lock to a sx-lock then to a x-lock since the thread is the only thread has the s-lock.
mysql> show engine innodb status\G
*******
Type: InnoDB
Name:
Status:
=======
2017-06-27 20:27:15 0x7f5dad5ef700 INNODB MONITOR OUTPUT
=======
Per second averages calculated from the last 18 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 125618 srv_active, 0 srv_shutdown, 1529371 srv_idle
srv_master_thread log flush and writes: 1654882
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 455165
--Thread 140039518410496 has waited at srv0srv.cc line 2320 for 624.00 seconds the semaphore:
X-lock on RW-latch at 0x7f5dae7ce398 created in file dict0dict.cc line 1198
a writer (thread id 140040582629120) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0purge.cc line 865
Last time write locked in file /mnt/workspace/
--Thread 140039501625088 has waited at btr0cur.cc line 1911 for 625.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f5da3efe0d0 created in file buf0buf.cc line 1456
a writer (thread id 140039501625088) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffefffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /mnt/workspace/
--Thread 140039585486592 has waited at buf0flu.cc line 1224 for 622.00 seconds the semaphore:
SX-lock on RW-latch at 0x7f5da3ff4790 created in file buf0buf.cc line 1456
a writer (thread id 140039501625088) has reserved it in mode SX
number of readers 0, waiters flag 1, lock_word: 10000000
Last time read locked in file not yet reserved line 0
Last time write locked in file /mnt/workspace/
--Thread 140039484839680 has waited at row0row.cc line 1073 for 625.00 seconds the semaphore:
S-lock on RW-latch at 0x7f5da4002950 created in file buf0buf.cc line 1456
a writer (thread id 140039501625088) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: ffffffffdfffffff
Last time read locked in file row0row.cc line 1073
Last time write locked in file /mnt/workspace/
--Thread 140039455500032 has waited at dict0stats.cc line 2375 for 616.00 seconds the semaphore:
X-lock on RW-latch at 0x7f5dae7ce398 created in file dict0dict.cc line 1198
a writer (thread id 140040582629120) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0purge.cc line 865
Last time write locked in file /mnt/workspace/
--Thread 140040582629120 has waited at dict0stats.cc line 3623 for 625.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f5dae7ce398 created in file dict0dict.cc line 1198
a writer (thread id 140040582629120) has reserved it in mode wait exclusive
number of readers 2, waiters flag 1, lock_word: fffffffffffffffe
Last time read locked in file row0purge.cc line 865
Last time write locked in file /mnt/workspace/
OS WAIT ARRAY INFO: signal count 456490
RW-shared spins 0, rounds 861311, OS waits 415991
RW-excl spins 0, rounds 712712, OS waits 8934
RW-sx spins 77047, rounds 893910, OS waits 3275
Spin rounds per wait: 861311.00 RW-shared, 712712.00 RW-excl, 11.60 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 31438233
Purge done for trx's n:o < 31438233 undo n:o < 0 state: running
History list length 9
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421515275276992, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421515275275800, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421515275274608, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
435768 OS file reads, 2565558 OS file writes, 1647024 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 62, seg size 64, 1552 merges
merged operations:
insert 396, delete mark 10642, delete 594
discarded operations:
insert 0, delete mark 0, delete 0
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
Hash table size 138389, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 31798899922
Log flushed up to 31798899922
Pages flushed up to 31792654680
Last checkpoint at 31792082305
Max checkpoint age 651585393
Checkpoint age target 631223350
Modified age 6245242
Checkpoint age 6817617
0 pending log flushes, 0 pending chkp writes
731006 log i/o's done, 0.00 log i/o's/second
-------
BUFFER POOL AND MEMORY
-------
Total large memory allocated 558891008
Dictionary memory allocated 516115751
Internal hash tables (constant factor + variable factor)
Adaptive hash index 8890560 (8856896 + 33664)
Page hash 553912 (buffer pool 0 only)
Dictionary cache 518329975 (2214224 + 516115751)
File system 18523272 (812272 + 17711000)
Lock system 1332584 (1329176 + 3408)
Recovery system 0 (0 + 0)
Buffer pool size 32764
Buffer pool size, bytes 0
Free buffers 1024
Database pages 31740
Old database pages 11696
Modified db pages 1682
Pending reads 0
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 106936, not young 10668248
0.00 youngs/s, 0.00 non-youngs/s
Pages read 431180, created 616607, written 1291654
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 31740, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
0 RW transactions active inside InnoDB
1 tablespace extents now reserved for B-tree split operations
Process ID=19203, Main thread ID=140039518410496, state: enforcing dict cache limit
Number of rows inserted 14188343, updated 531664, deleted 30275, read 63724948
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
-------
END OF INNODB MONITOR OUTPUT
=======
1 row in set (0.00 sec)
GDB Stacktrace for Thread 140039501625088:
#0 0x00007f5dbcd196d5 in pthread_
#1 0x0000000000fa802b in wait (this=<optimized out>) at /mnt/workspace/
#2 os_event::wait_low (this=0x7f5da3e
#3 0x0000000000fa837a in os_event_wait_low (event=<optimized out>, reset_sig_
at /mnt/workspace/
#4 0x00000000010658f1 in sync_array_
at /mnt/workspace/
#5 0x000000000106805d in rw_lock_
threshold=
#6 rw_lock_x_lock_low (line=1911, file_name=0x15e15e0 "/mnt/workspace
at /mnt/workspace/
#7 rw_lock_x_lock_func (lock=0x7f5da3e
line=
#8 0x00000000010f041d in pfs_rw_
file_
at /mnt/workspace/
#9 0x00000000010f72d1 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=
file=
dirty_
#10 0x00000000010cda9d in btr_block_get_func (page_id=..., page_size=..., mode=mode@entry=2, line=line@
file=0x15e15e0 "/mnt/workspace
at /mnt/workspace/
#11 0x00000000010d8ae3 in btr_cur_
has_
mtr=
#12 0x00000000010c0619 in btr_page_
file=0x15e05d8 "/mnt/workspace
at /mnt/workspace/
#13 0x00000000010c0b35 in btr_page_
at /mnt/workspace/
#14 0x00000000010c7a5b in btr_compress (cursor=
at /mnt/workspace/
#15 0x00000000010d5a6c in btr_cur_
at /mnt/workspace/
#16 0x00000000010db9e9 in btr_cur_
mtr=
#17 0x00000000010c847e in btr_compress (cursor=
at /mnt/workspace/
#18 0x00000000010d5a6c in btr_cur_
at /mnt/workspace/
---Type <return> to continue, or q <return> to quit---
#19 0x00000000010db9e9 in btr_cur_
mtr=
#20 0x000000000101aac9 in row_purge_
at /mnt/workspace/
#21 0x000000000101c158 in row_purge_
at /mnt/workspace/
#22 row_purge_
at /mnt/workspace/
#23 0x000000000101c869 in row_purge_
at /mnt/workspace/
#24 row_purge (thr=0x7f5d7cbf
#25 row_purge_step (thr=thr@
#26 0x0000000000fca11c in que_thr_step (thr=0x6) at /mnt/workspace/
#27 que_run_threads_low (thr=0x6) at /mnt/workspace/
#28 que_run_threads (thr=thr@
#29 0x0000000001053c11 in srv_task_execute () at /mnt/workspace/
#30 srv_worker_thread (arg=<optimized out>) at /mnt/workspace/
#31 0x00007f5dbcd15dc5 in start_thread () from /lib64/
#32 0x00007f5dbaf66ced in clone () from /lib64/libc.so.6
| description: | updated |
| Shahriyar Rzayev (rzayev-sehriyar) wrote | #1 |
Percona now uses JIRA for bug reports so this bug report is migrated to: https:/