Bug #73890 Error: semaphore wait has lasted > 600 seconds
Submitted: 11 Sep 2014 13:01 Modified: 30 Apr 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:Microsoft Windows (Server 2008)
Assigned to: MySQL Verification Team CPU Architecture:Any

[11 Sep 2014 13:01] Mike Willbanks
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.
[11 Sep 2014 13:02] Mike Willbanks
my.ini configuration

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

[11 Sep 2014 13:03] Mike Willbanks
Error Log

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

[4 Nov 2014 22:46] MySQL Verification Team
http://bugs.mysql.com/bug.php?id=74684 marked as duplicate of this one.
[7 Nov 2014 21:54] MySQL Verification Team
http://bugs.mysql.com/bug.php?id=74743 marked as duplicate of this one.
[10 Nov 2014 14:19] Laurenz Albe
I am affected by that bug.
Is there anything I can do to help speed up resolution?
[24 Nov 2014 7:58] Laurenz Albe
Happened again yesterday morning (Linux x86_64).
Is there anything I can do to shed light on this?
[9 Feb 2015 18:00] MySQL Verification Team
stack traces from the minidump, mysqld.dmp

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

[9 Feb 2015 18:16] MySQL Verification Team
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
[9 Feb 2015 18:52] MySQL Verification Team
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',
....
[23 Apr 2015 14:08] Clint Priest
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...
[15 Jul 2015 7:48] MySQL Verification Team
http://bugs.mysql.com/bug.php?id=77723 marked as duplicate of this
[15 Sep 2015 3:39] Toshikuni Fukaya
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
[15 Sep 2015 3:42] Toshikuni Fukaya
miss.
correct one is https://bugs.mysql.com/bug.php?id=32149
[20 Nov 2015 8:36] Spiros Ioannou
Just happened on: 
mysql  Ver 14.14 Distrib 5.5.46, for Linux (x86_64) using readline 5.1
[25 Feb 2016 16:50] Steve S.
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
[13 Apr 2016 22:36] MySQL Verification Team
http://bugs.mysql.com/bug.php?id=81074 marked as duplicate of this one.
[23 Dec 2016 10:49] Stefan Ring
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.
[24 Dec 2016 23:31] Stefan Ring
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.
[27 Apr 2017 18:52] MySQL Verification Team
https://bugs.mysql.com/bug.php?id=86116 marked as duplicate of this one.
[29 Sep 2017 14:23] Roland Walter
I the same bug on Windows 10 Pro 1703 for mysql-5.6.37-winx64.
[12 Apr 2018 15:50] TheaterMania Company
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!
[17 Apr 2018 5:02] MySQL Verification Team
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
[18 May 2018 1:00] Bugs System
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".
[27 Aug 2018 1:00] Bugs System
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".
[26 Mar 2019 20:09] Westlake IT
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
[24 Mar 21:27] sviatoslav apanasyonok
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?
[24 Mar 22:06] MySQL Verification Team
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
[25 Mar 4:11] sviatoslav apanasyonok
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?
[25 Mar 5:34] MySQL Verification Team
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...
[30 Mar 15:46] sviatoslav apanasyonok
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.
[30 Mar 18:18] MySQL Verification Team
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
[31 Mar 13:10] sviatoslav apanasyonok
mysql debug log

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

[1 May 1:00] Bugs System
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".