MySQL Bugs: #73890: Error: semaphore wait has lasted

Bug #73890	Error: semaphore wait has lasted > 600 seconds
Submitted:	11 Sep 2014 13:01	Modified:	30 Apr 2021 18:18
Reporter:	Mike Willbanks	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S1 (Critical)
Version:	5.5.39/5.7	OS:	Windows (Server 2008)
Assigned to:	MySQL Verification Team	CPU Architecture:	Any

Description:
MySQL server crashes daily to every 3 days due to a semaphore wait.  We've tuned memory as much as possible, lightened the load on the server by forcing reads against a replicant and still are encountering these issues.

The error log is showing the following:
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.
140911  8:32:01  InnoDB: Assertion failure in thread 3196 in file srv0srv.c line 2502

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4003577, signal count 18944453
--Thread 4644 has waited at btr0sea.c line 1134 for 942.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 00000000220AFE68 created in file btr0sea.c line 178
a writer (thread id 4644) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.c line 1057
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\btr\btr0sea.c line 1382
--Thread 2684 has waited at row0purge.c line 680 for 939.00 seconds the semaphore:
S-lock on RW-latch at 0000000140127080 created in file dict0dict.c line 738
a writer (thread id 4644) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0ins.c line 1550
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\row\row0mysql.c line 3151
--Thread 3996 has waited at btr0cur.c line 1929 for 938.00 seconds the semaphore:
X-lock on RW-latch at 00000000220AFE68 created in file btr0sea.c line 178
a writer (thread id 4644) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time read locked in file btr0sea.c line 1057
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\btr\btr0sea.c line 1382
--Thread 3280 has waited at row0ins.c line 2027 for 938.00 seconds the semaphore:
X-lock on RW-latch at 00000001472BF3C0 created in file buf0buf.c line 938
a writer (thread id 3996) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3908
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\row\row0upd.c line 2144
--Thread 668 has waited at row0ins.c line 2027 for 937.00 seconds the semaphore:
X-lock on RW-latch at 00000001472BF3C0 created in file buf0buf.c line 938
a writer (thread id 3996) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3908
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\row\row0upd.c line 2144
--Thread 4224 has waited at row0ins.c line 2027 for 937.00 seconds the semaphore:
X-lock on RW-latch at 00000001472BF3C0 created in file buf0buf.c line 938
a writer (thread id 3996) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3908
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\row\row0upd.c line 2144
--Thread 5000 has waited at row0ins.c line 2027 for 937.00 seconds the semaphore:
X-lock on RW-latch at 00000001472BF3C0 created in file buf0buf.c line 938
a writer (thread id 3996) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3908
Last time write locked in file ..\..\..\mysql-5.5.39\storage\innobase\row\row0upd.c line 2144
--Thread 4576 has waited at dict0dict.c line 351 for 1.00 seconds the semaphore:
Mutex at 000000002CD7FDA8 created file dict0dict.c line 725, lock var 1
waiters flag 1
Mutex spin waits 254411693, rounds 446502597, OS waits 2071160
RW-shared spins 5583200, rounds 27946126, OS waits 310712
RW-excl spins 8599389, rounds 91662438, OS waits 1456610
Spin rounds per wait: 1.76 mutex, 5.01 RW-shared, 10.66 RW-excl

I've attached the errorlog, my.ini and core dump.

How to repeat:
Unknown.

my.ini configuration

Attachment: my.ini (application/octet-stream, text), 8.93 KiB.

Error Log

Attachment: mysql-error-log (application/octet-stream, text), 16.83 KiB.

http://bugs.mysql.com/bug.php?id=74684 marked as duplicate of this one.

http://bugs.mysql.com/bug.php?id=74743 marked as duplicate of this one.

I am affected by that bug.
Is there anything I can do to help speed up resolution?

Happened again yesterday morning (Linux x86_64).
Is there anything I can do to shed light on this?

stack traces from the minidump, mysqld.dmp

Attachment: bug73890_5.5.39-winx64-minidump.txt (text/plain), 80.13 KiB.

Stack trace looks like the destructor of THD object locks LOCK_thread_count while it goes on to do a bunch of innodb things like removing the temporary tables which in turn waits for btr_search_latch.  
Not sure who owns that without reading more code.

Stored procedure and new any connections wait for LOCK_thread_count.

LOCK_Open is locked by the background thread who flushes tables due to "flush_time" variable.

I guess a temporary remedy to try could involve:
o) drop all temporary tables explicitly instead of rely on disconnect to cleanup
o) set flush_time=0 to disable background flushing of tables
o) set innodb_adaptive_hash_index=0

Looks like deadlock is simple as this:

thread (0x1224) waits for btr_search_latch;
thread (0x1224) owns LOCK_thread_count
thread (0xc88)  waits for LOCK_thread_count;  
thread (0xc88)  owns btr_search_latch

thread (0x1224) was some code in the Event Scheduler
that created an innodb temporary table but didn't explicitly drop it.
That dropping happens in the event scheduler cleanup:

---TRANSACTION A5BE9197C, ACTIVE 942 sec dropping table
11 lock struct(s), heap size 3112, 6 row lock(s)
MySQL thread id 94304, OS thread handle 0x1224, query id 0 event_scheduler Clearing

thread (0xc88) is some query with many joins and involving a stored function,
and apparently also holds the btr_search_latch according to innodb status, 
but I'm not seeing where it acquired this lock from the stack traces?

---TRANSACTION A5BE9196F, ACTIVE 943 sec, thread declared inside InnoDB 69
mysql tables in use 80, locked 0
, holds adaptive hash latch
MySQL thread id 94305, OS thread handle 0xc88, query id 63850896 23.23.229.30 mysql
(
    select
    n.nodeId,
    lpad(hex(n.nodeId), 16, '0') as 'guids',
....

I followed a trace of bugs all pointing as duplicates of this one.  Not sure that this is *exactly* the same.  We recently upgraded to 5.6 and are now experiencing this on RHEL6.  Begnning of INNODB MONITOR OUTPUT shows this:

--Thread 140251174065920 has waited at dict0stats.cc line 2385 for 241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x1347260 '&dict_operation_lock'
a writer (thread id 140251174065920) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file row0undo.cc line 298
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.23-72.1/storage/innob
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 1, pwrites 0

If you look, the same thread id 140251174065920 is trying to aquire a lock it already has...

Can attach a 10 minute INNODB MONITOR output trace if you want it...

http://bugs.mysql.com/bug.php?id=77723 marked as duplicate of this

I encountered this bug too.
I use MySQL 5.6.24 on Ubuntu 14.04LTS 64bit.

I think this is related to https://bugs.mysql.com/bug.php?id=73890

miss.
correct one is https://bugs.mysql.com/bug.php?id=32149

Just happened on: 
mysql  Ver 14.14 Distrib 5.5.46, for Linux (x86_64) using readline 5.1

This crash happened to us twice on different servers just this week.  Both servers run this version:

5.6.14-rel62.0-log
Percona Server with XtraDB (GPL), Release rel62.0, Revision 483

http://bugs.mysql.com/bug.php?id=81074 marked as duplicate of this one.

After having scratched my head quite a lot how it is possible that a thread is waiting on an X-lock with lock_word 0 (and even appearing to wait on itself), like in #74684, and like it happened to me recently, I think I have found a possibility:

thread 1 holds x lock
thread 1 recurses 2048 times and overflows it
thread 2 tries to x lock
  because lock_word is positive, rw_lock_lock_word_decr reports success, the thread sets itself as writer and goes on to wait
thread 1 exits overflowing recursion, returning lock_word to negative
thread 2 sees negative lock_word and waits on event
thread 1 exits all the way, returning lock_word to 0
  x unlocking only wakes other threads when the lock_word goes back to X_LOCK_DECR (the initial value), which it does not do because thread 2 has decreased it by one decrement

This train of thought was inspired by <https://github.com/mysql/mysql-server/commit/b79efeda435d8af3707f7002506819866eae199f>. There does not seem to be any more information on this, but it hints at a high degree of recursion being possible/expected, and it changes the mechanism so that overflow cannot realistically happen with a sane stack size.

Damn, lock_word is 64 bits on Linux where I have seen this, so the overflow cannot happen. It’s still possible on Windows, though, I guess.

https://bugs.mysql.com/bug.php?id=86116 marked as duplicate of this one.

I the same bug on Windows 10 Pro 1703 for mysql-5.6.37-winx64.

This occurs on my system. It doesn't crash, but it hangs the database for about 10 minutes (600 seconds). The database where this occurs is a slave with read-only=1. So, the only writes occurring are from replication.

My configuration is MySQL 5.6 and CentOS 6.9.

This bug is 3 1/2 years old. Are there any updates on when this may be addressed?

Thank you!

Hi all,

We do have some info from the crashes but I can't reproduce this at all. Any chance that someone who can reproduce this often can run a -dev build of mysqld so we can get bit more data out of it?

thanks
Bogdan

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

We have the similar issue on our production server
Last time write locked in file /mnt/workspace/percona-server-5.7-redhat-binary-rocks/label_exp/centos7-64/rpmbuild/BUILD/percona-server-5.7.19-17/percona-server-5.7.
19-17/storage/innobase/include/btr0sea.ic line 90
--Thread 140295937165056 has waited at btr0sea.cc line 1271 for 1.00 seconds the semaphore:
S-lock on RW-latch at 0x428cd88 created in file btr0sea.cc line 230
a writer (thread id 140295836526336) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 1271
Last time write locked in file /mnt/workspace/percona-server-5.7-redhat-binary-rocks/label_exp/centos7-64/rpmbuild/BUILD/percona-server-5.7.19-17/percona-server-5.7.
19-17/storage/innobase/btr/btr0sea.cc line 1368
--Thread 140295819740928 has waited at btr0sea.cc line 1271 for 1.00 seconds the semaphore:
S-lock on RW-latch at 0x428cd88 created in file btr0sea.cc line 230
a writer (thread id 140295836526336) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.cc line 1271
Last time write locked in file /mnt/workspace/percona-server-5.7-redhat-binary-rocks/label_exp/centos7-64/rpmbuild/BUILD/percona-server-5.7.19-17/percona-server-5.7.19-17/storage/innobase/btr/btr0sea.cc line 1368
--Thread 140297940809472 has waited at btr0sea.ic line 90 for 1.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x428c968 created in file btr0sea.cc line 230
a writer (thread id 140297940809472) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.ic line 128
Last time write locked in file /mnt/workspace/percona-server-5.7-redhat-binary-rocks/label_exp/centos7-64/rpmbuild/BUILD/percona-server-5.7.19-17/percona-server-5.7.19-17/storage/innobase/include/btr0sea.ic line 90
--Thread 140296230909696 has waited at ibuf0ibuf.cc line 4568 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7faed2f02110 created in file buf0buf.cc line 1456
a writer (thread id 140296247695104) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: fffffffff0000000
Last time read locked in file ibuf0ibuf.cc line 4568
Last time write locked in file /mnt/workspace/percona-server-5.7-redhat-binary-rocks/label_exp/centos7-64/rpmbuild/BUILD/percona-server-5.7.19-17/percona-server-5.7.19-17/storage/innobase/ibuf/ibuf0ibuf.cc line 406
OS WAIT ARRAY INFO: signal count 122634005
RW-shared spins 0, rounds 330300456, OS waits 99912586
RW-excl spins 0, rounds 925849588, OS waits 5741473
RW-sx spins 3805140, rounds 49373413, OS waits 946595
Spin rounds per wait: 330300456.00 RW-shared, 925849588.00 RW-excl, 12.98 RW-sx

Unfortunetly  I cannot run it as -dev

Hi. I experience this issue very often. I use mysql server 5.7.28 docker image.
I saw a comment  'We do have some info from the crashes but I can't reproduce this at all. Any chance that someone who can reproduce this often can run a -dev build of mysqld so we can get bit more data out of it?'

How can I make dev build of mysqld? Is there any instruction? Or maybe you can give me a link for already built binaries or docker image?

From the Manual you could get instructions to build a server from source:

Chapter 2 Installing MySQL Using a Standard Source Distribution

https://dev.mysql.com/doc/mysql-sourcebuild-excerpt/8.0/en/installing-source-distribution....

Chapter 3 Installing MySQL Using a Development Source Tree
https://dev.mysql.com/doc/mysql-sourcebuild-excerpt/8.0/en/installing-development-tree.htm...

Chapter 4 MySQL Source-Configuration Options
https://dev.mysql.com/doc/mysql-sourcebuild-excerpt/8.0/en/source-configuration-options.ht...

Chapter 5 Dealing with Problems Compiling MySQL
https://dev.mysql.com/doc/mysql-sourcebuild-excerpt/8.0/en/compilation-problems.html

I see many options on this page:
https://dev.mysql.com/doc/mysql-sourcebuild-excerpt/5.7/en/source-configuration-options.ht...
Which of them I have to set and with which values to make dev build in order to get more information when error occurs?

Hi,

As far as I know we do not have produce dev build in docker images, can't confirm no one else produces them.

As for creating a debug build look at here:
https://dev.mysql.com/doc/internals/en/cmake-howto-quick-debug-configuration.html

So basically you just set a build type to debug

-DCMAKE_BUILD_TYPE=Debug

you can see other build options:
https://dev.mysql.com/doc/mysql-sourcebuild-excerpt/8.0/en/source-configuration-options.ht...

Hi!
Eventually I was able to build debug version of mysql server and make docker image.

Now I run it with --debug option. Full cmd:

mysqld --character-set-server=utf8 --collation-server=utf8_general_ci --max_connections=150 --debug

But it produces to much log output (about 1GB/minute) and work too slow. I'm not sure that I can reproduce error with such configuration. And even if I can reproduce the error, it still will be hard to find useful information in such big log file.

On page https://dev.mysql.com/doc/refman/5.7/en/making-trace-files.html I see
that it possible to configure what should be debugged. There is example of debug option with parameters:

mysqld --debug=d,info,error,query,general,where:O,/tmp/mysqld.trace

Questions:
What is proper options for debug option regarding this issue?
Do I need to start mysqld with extra options (except debug)?

It would be nice if someone could give me full cmd for mysqld.

Hi,

Thanks for testing. Can you run this debug build but run the mysqld without --debug we should still get more data if you manage to reproduce the problem.

Thanks
Bogdan

mysql debug log

Attachment: mysql-debug.log.txt (text/plain), 38.90 KiB.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Just had this same issue on a production server running MySQL 5.7.33 (Debian Stretch). Didn't crash, but just locked up until I forcefully restarted MySQL.

Recently had this on another Production Server (5.7.32). Only way to resolve it was to force restart the database.

We got what seems to be the same problem with version 8.0.30 on a Windows Server.
It only happened once so far so we cannot reproduce.
That wass on a read-only replication slave and the error log was:

InnoDB: ###### Diagnostic info printed to the standard error stream
2022-09-27T06:41:46.114666Z 0 [ERROR] [MY-012872] [InnoDB] [FATAL] Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2022-09-27T06:41:46.115239Z 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: srv0srv.cc:1867:ib::fatal triggered thread 5104
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/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
06:41:46 UTC - mysqld got exception 0x16 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
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...
7ff7394e0858    mysqld.exe!?my_print_stacktrace@@YAXPEBEK@Z()
7ff73867e92b    mysqld.exe!?print_fatal_signal@@YAXH@Z()
7ff73867e6f3    mysqld.exe!?my_server_abort@@YAXXZ()
7ff7394c47fa    mysqld.exe!?my_abort@@YAXXZ()
7ff73970ca99    mysqld.exe!?deallocate@?$allocator@V?$sub_match@V?$_String_const_iterator@V?$_String_val@U?$_Simple_types@D@std@@@std@@@std@@@std@@@std@@QEAAXQEAV?$sub_match@V?$_String_const_iterator@V?$_String_val@U?$_Simple_types@D@std@@@std@@@std@@@2@_K@Z()
7ff7395e9643    mysqld.exe!??$endl@DU?$char_traits@D@std@@@std@@YAAEAV?$basic_ostream@DU?$char_traits@D@std@@@0@AEAV10@@Z()
7ff7395e4a06    mysqld.exe!??$endl@DU?$char_traits@D@std@@@std@@YAAEAV?$basic_ostream@DU?$char_traits@D@std@@@0@AEAV10@@Z()
7ff7396a033d    mysqld.exe!?deallocate@?$allocator@V?$sub_match@V?$_String_const_iterator@V?$_String_val@U?$_Simple_types@D@std@@@std@@@std@@@std@@@std@@QEAAXQEAV?$sub_match@V?$_String_const_iterator@V?$_String_val@U?$_Simple_types@D@std@@@std@@@std@@@2@_K@Z()
7ffd920ef4a0    ucrtbase.DLL!_o__realloc_base()
7ffd9e4c1412    KERNEL32.DLL!???
7ffda0b05504    ntdll.dll!RtlUserThreadStart()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.