MySQL Bugs: #96135: mysql server bug

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

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.

mysql error log

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

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.