Bug #96135 mysql server bug
Submitted: 9 Jul 2019 7:36 Modified: 9 Jul 2019 12:33
Reporter: FuLi Wang Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:mysql-8.0.16-linux-glibc2.12-x86_64 OS:CentOS (3.10.0-123.el7.x86_64)
Assigned to: CPU Architecture:x86 (x86_64)
Tags: A long semaphore wait

[9 Jul 2019 7:36] FuLi Wang
Description:
2019-07-09T14:43:18.564181+08:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140290602391296 has waited at trx0undo.ic line 129 for 241.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97cbd1f408 created in file buf0buf.cc line 781
a writer (thread id 140286239930112) 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 ../../../mysql-8.0.16/storage/innobase/buf/buf0flu.cc line 1328
2019-07-09T14:43:18.564243+08:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140290601809664 has waited at row0ins.cc line 2412 for 241.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
=====================================
2019-07-09 14:43:32 0x7f96a7ffe700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 59 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 2823 srv_active, 0 srv_shutdown, 64450 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 456
--Thread 140290635523840 has waited at row0ins.cc line 2412 for 55.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
--Thread 140290602391296 has waited at trx0undo.ic line 129 for 255.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97cbd1f408 created in file buf0buf.cc line 781
a writer (thread id 140286239930112) 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 ../../../mysql-8.0.16/storage/innobase/buf/buf0flu.cc line 1328
--Thread 140290601809664 has waited at row0ins.cc line 2412 for 255.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
--Thread 140284235085568 has waited at trx0purge.cc line 497 for 153.00 seconds the semaphore:
Mutex at 0x7f97ec816760, Mutex UNDO_SPACE_RSEG created trx0rseg.cc:191, lock var 1

--Thread 140290599483136 has waited at row0ins.cc line 2412 for 55.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
--Thread 140290600937216 has waited at row0ins.cc line 2412 for 55.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
--Thread 140290600355584 has waited at row0ins.cc line 2412 for 35.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
--Thread 140290636687104 has waited at row0ins.cc line 2412 for 34.00 seconds the semaphore:
X-lock on RW-latch at 0x7f97c3ab6908 created in file buf0buf.cc line 781
a writer (thread id 140290602391296) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file ../../../mysql-8.0.16/storage/innobase/btr/btr0sea.cc line 942
OS WAIT ARRAY INFO: signal count 449
RW-shared spins 21, rounds 23, OS waits 2
RW-excl spins 121, rounds 1655, OS waits 44
RW-sx spins 5, rounds 100, OS waits 3
Spin rounds per wait: 1.10 RW-shared, 13.68 RW-excl, 20.00 RW-sx

How to repeat:
It happens once every two or three days.
[9 Jul 2019 7:38] FuLi Wang
mysql error log

Attachment: bug.log (text/x-log), 602.01 KiB.

[9 Jul 2019 12:33] Sinisa Milivojevic
Hi Mr. Wang,

Thank you for your bug report.

However, this does not look like a bug. This is a consequence of the misconfiguration or a consequence of some very slow hardware. It is also possible that your system is under the load that it can't sustain. However, the last option looks most likely, since this wait occurs due to the refreshment of the index pages from the redo log.

I also do not see how could we repeat this problem that you report.

And, as I wrote , 8.0.16 has so many tuning options that you can tune your InnoDB SE and OS to make the problem go away.