Hey gang,
We’ve had several issues with server crashes due to semaphore timeouts over the past couple of months, and I’m having a hard time tracking them down. When a crash happens, it seems that there are many operations that come close to causing a timeout leading up to it. I found this article (Troubleshooting MySQL Crashes Webinar: Q&A - Percona Database Performance Blog) and it says to dig through the source code, so I’m hoping to get a little help from someone who’s had some experience looking through the MySQL source code before, as this will be my first time doing so.
I’ve included the tail of the MySQL error log file the last time this happened. We also have slow query logging turned on, but I didn’t find any queries that showed a lock time even over 1 second. I included the relevant slow query log during that time as well, at the very bottom after the error log.
Any help would be great - I’m grasping at straws here.
2022-07-04T14:23:06.729096-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140266137093888 has waited at btr0sea.cc line 1698 for 300 seconds the semaphore:
X-lock on RW-latch at 0x7fb9802e7250 created in file btr0sea.cc line 201
a writer (thread id 140304799545088) has reserved it in mode wait exclusive
number of readers 1 (thread id 140371441366784), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729127-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140248878049024 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e7790 created in file btr0sea.cc line 201
a writer (thread id 140386807961344) has reserved it in mode wait exclusive
number of readers 1 (thread id 140248901297920), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729158-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140266134980352 has waited at btr0sea.cc line 1698 for 302 seconds the semaphore:
X-lock on RW-latch at 0x7fb9802e7250 created in file btr0sea.cc line 201
a writer (thread id 140304799545088) has reserved it in mode wait exclusive
number of readers 1 (thread id 140371441366784), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729192-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140269686372096 has waited at btr0sea.cc line 1698 for 303 seconds the semaphore:
X-lock on RW-latch at 0x7fb9802e7250 created in file btr0sea.cc line 201
a writer (thread id 140304799545088) has reserved it in mode wait exclusive
number of readers 1 (thread id 140371441366784), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729223-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140239075579648 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e75d0 created in file btr0sea.cc line 201
a writer (thread id 140311303489280) has reserved it in mode wait exclusive
number of readers 1 (thread id 140283105830656), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729254-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140331806107392 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e7090 created in file btr0sea.cc line 201
a writer (thread id 140387482371840) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0sea.cc line 1443
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 1544
2022-07-04T14:23:06.729281-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140342246545152 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e75d0 created in file btr0sea.cc line 201
a writer (thread id 140311303489280) has reserved it in mode wait exclusive
number of readers 1 (thread id 140283105830656), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729316-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140269722302208 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e75d0 created in file btr0sea.cc line 201
a writer (thread id 140311303489280) has reserved it in mode wait exclusive
number of readers 1 (thread id 140283105830656), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729347-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140269699061504 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802f5810 created in file btr0sea.cc line 201
a writer (thread id 140248918206208) has reserved it in mode wait exclusive
number of readers 1 (thread id 140386805856000), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729377-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140352777246464 has waited at btr0sea.cc line 1443 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e7410 created in file btr0sea.cc line 201
a writer (thread id 140342948640512) has reserved it in mode wait exclusive
number of readers 1 (thread id 140283096319744), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 1900
2022-07-04T14:23:06.729408-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140261244790528 has waited at btr0sea.cc line 920 for 303 seconds the semaphore:
S-lock on RW-latch at 0x7fb9802e75d0 created in file btr0sea.cc line 201
a writer (thread id 140311303489280) has reserved it in mode wait exclusive
number of readers 1 (thread id 140283105830656), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729443-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140433054545664 has waited at buf0flu.cc line 928 for 303 seconds the semaphore:
Mutex at 0x7fb9803477e0, Mutex BUF_POOL_FLUSH_STATE created buf0buf.cc:1243, lock var 1
2022-07-04T14:23:06.729459-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140254611867392 has waited at btr0sea.cc line 1698 for 299 seconds the semaphore:
X-lock on RW-latch at 0x7fb9802e7250 created in file btr0sea.cc line 201
a writer (thread id 140304799545088) has reserved it in mode wait exclusive
number of readers 1 (thread id 140371441366784), waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 920
Last time write locked in file /mnt/jenkins/workspace/ps8.0-autobuild-RELEASE/test/percona-server-8.0.27-18/storage/innobase/btr/btr0sea.cc line 693
2022-07-04T14:23:06.729490-05:00 0 [Warning] [MY-012985] [InnoDB] A long semaphore wait:
--Thread 140410491307776 has waited at buf0flu.cc line 1990 for 303 seconds the semaphore:
Mutex at 0x7fb980353200, Mutex BUF_POOL_LRU_LIST created buf0buf.cc:1238, lock var 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
Hash table size 209044679, node heap has 283047 buffer(s)
Hash table size 209044679, node heap has 344707 buffer(s)
Hash table size 209044679, node heap has 213852 buffer(s)
Hash table size 209044679, node heap has 228864 buffer(s)
Hash table size 209044679, node heap has 364166 buffer(s)
Hash table size 209044679, node heap has 503249 buffer(s)
Hash table size 209044679, node heap has 494332 buffer(s)
Hash table size 209044679, node heap has 383474 buffer(s)
1295.08 hash searches/s, 531.54 non-hash searches/s
---
LOG
---
Log sequence number 307517514369287
Log buffer assigned up to 307517514369287
Log buffer completed up to 307517514369287
Log written up to 307517514369059
Log flushed up to 307517514337258
Added dirty pages up to 307517514369287
Pages flushed up to 307515615626671
Last checkpoint at 307515615626671
Checkpoint age target 5913622528
Modified age no less than 1897798902
Checkpoint age 1898742616
Max checkpoint age 5771899392
Number of logs 3
Log size 2147483648
Log total size 6442450944
17388192558 log i/o's done, 0.13 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 6764567
Buffer pool size 51570536
Buffer pool size, bytes 844931661824
Free buffers 8536
Database pages 50515188
Old database pages 18647045
Modified db pages 247492
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 321029233, not young 6850869130
0.00 youngs/s, 0.00 non-youngs/s
Pages read 280358688, created 55145804, written 390251524
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 50515188, unzip_LRU len: 5051542
I/O sum[0]:cur[312], unzip sum[0]:cur[8]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1068
Database pages 6316841
Old database pages 2331782
Modified db pages 30553
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 41279497, not young 851789851
0.00 youngs/s, 0.00 non-youngs/s
Pages read 35105381, created 6868536, written 49472055
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6316841, unzip_LRU len: 631693
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 1
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1070
Database pages 6309631
Old database pages 2329121
Modified db pages 30471
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 40717567, not young 851707081
0.00 youngs/s, 0.00 non-youngs/s
Pages read 35258374, created 6869707, written 47955370
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6309631, unzip_LRU len: 630963
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 2
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1054
Database pages 6315852
Old database pages 2331417
Modified db pages 29753
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 40443871, not young 868224703
0.00 youngs/s, 0.00 non-youngs/s
Pages read 35149716, created 6938479, written 48349627
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6315852, unzip_LRU len: 631585
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 3
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1059
Database pages 6315750
Old database pages 2331379
Modified db pages 31313
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 39650487, not young 858438719
0.00 youngs/s, 0.00 non-youngs/s
Pages read 35108428, created 6781355, written 48325727
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6315750, unzip_LRU len: 631577
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 4
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1076
Database pages 6317868
Old database pages 2332161
Modified db pages 29805
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 39421910, not young 845322573
0.00 youngs/s, 0.00 non-youngs/s
Pages read 34959451, created 6803859, written 48323801
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6317868, unzip_LRU len: 631787
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 5
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1073
Database pages 6307821
Old database pages 2328453
Modified db pages 30876
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 39977413, not young 861511184
0.00 youngs/s, 0.00 non-youngs/s
Pages read 35229243, created 6904237, written 48093669
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6307821, unzip_LRU len: 630786
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 6
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1069
Database pages 6320903
Old database pages 2333282
Modified db pages 32244
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 40113041, not young 857742850
0.00 youngs/s, 0.00 non-youngs/s
Pages read 34799528, created 6984522, written 49609965
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6320903, unzip_LRU len: 632093
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
---BUFFER POOL 7
Buffer pool size 6446317
Buffer pool size, bytes 105616457728
Free buffers 1067
Database pages 6310522
Old database pages 2329450
Modified db pages 32477
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 39425447, not young 856132169
0.00 youngs/s, 0.00 non-youngs/s
Pages read 34748567, created 6995109, written 50121310
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6310522, unzip_LRU len: 631058
I/O sum[0]:cur[39], unzip sum[0]:cur[1]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
98 read views open inside InnoDB
25 RW transactions active inside InnoDB
---OLDEST VIEW---
Read view low limit trx n:o 710155708088
Trx read view will not see trx with id >= 710155708088, sees < 710154861085
Read view individually stored trx ids:
Read view trx id 710154861085
Read view trx id 710155699392
Read view trx id 710155707656
Read view trx id 710155707815
Read view trx id 710155708015
-----------------
Process ID=5542, Main thread ID=140409155397376 , state=sleeping
Number of rows inserted 893874364, updated 781992141, deleted 834889087, read 15445704736305
0.36 inserts/s, 1.19 updates/s, 0.00 deletes/s, 1348.32 reads/s
Number of system rows inserted 304856167, updated 918294050, deleted 77087821, read 10116009611
0.06 inserts/s, 0.44 updates/s, 0.00 deletes/s, 0.44 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================