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: | |
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 |
[11 Sep 2014 13:01]
Mike Willbanks
[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 2021 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 2021 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 2021 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 2021 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 2021 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 2021 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 2021 13:10]
sviatoslav apanasyonok
mysql debug log
Attachment: mysql-debug.log.txt (text/plain), 38.90 KiB.
[1 May 2021 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".
[7 Jun 2021 14:55]
IGG t
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.
[10 Sep 2021 14:33]
IGG t
Recently had this on another Production Server (5.7.32). Only way to resolve it was to force restart the database.
[28 Sep 2022 11:07]
Guillaume Toison
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.