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.
[28 Apr 2023 2:21]
huifa huang
I the same bug on CentOS Linux release 7.0.1406 for mysql-8.0.33-linux-glibc2.12-x86_64. InnoDB: ###### Diagnostic info printed to the standard error stream 2023-04-28T04:44:58.942679+08:00 0 [ERROR] [MY-012872] [InnoDB] [FATAL] Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung. 2023-04-28T04:44:58.942714+08:00 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: srv0srv.cc:1878:ib::fatal triggered thread 140382012700416 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. 2023-04-27T20:44:58Z UTC - mysqld got signal 6 ; Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware. BuildID[sha1]=acbc49ebed904cdd4e3e61226adcda0a8c0ad719 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... stack_bottom = 0 thread_stack 0x100000 /data/mysql8.0/app/mysql/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x2e) [0x208e8ce] /data/mysql8.0/app/mysql/bin/mysqld(print_fatal_signal(int)+0x3c3) [0x1121da3] /data/mysql8.0/app/mysql/bin/mysqld(my_server_abort()+0x5e) [0x1121eae] /data/mysql8.0/app/mysql/bin/mysqld(my_abort()+0xa) [0x2088bda] /data/mysql8.0/app/mysql/bin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0x30c) [0x22cbf4c] /data/mysql8.0/app/mysql/bin/mysqld(ib::fatal::~fatal()+0x98) [0x22ceae8] /data/mysql8.0/app/mysql/bin/mysqld(srv_error_monitor_thread()+0x470) [0x22660e0] /data/mysql8.0/app/mysql/bin/mysqld(std::thread::_State_impl<std::thread::_Invoker<std::tuple<Detached_thread, void (*)()> > >::_M_run()+0xc4) [0x218bb74] /data/mysql8.0/app/mysql/bin/mysqld() [0x2a929ff] /lib64/libpthread.so.0(+0x7ea5) [0x7fb22cfa0ea5] /lib64/libc.so.6(clone+0x6d) [0x7fb22b2a88dd] 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. 2023-04-28T04:44:59.244222+08:00 0 [System] [MY-010116] [Server] /data/mysql8.0/app/mysql/bin/mysqld (mysqld 8.0.33) starting as process 26462 2023-04-28T04:44:59.253765+08:00 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started. 2023-04-28T04:45:10.820100+08:00 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended. 2023-04-28T04:45:24.780624+08:00 0 [System] [MY-010229] [Server] Starting XA crash recovery... 2023-04-28T04:45:24.786623+08:00 0 [System] [MY-010232] [Server] XA crash recovery finished. 2023-04-28T04:45:27.756630+08:00 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed. 2023-04-28T04:45:27.756668+08:00 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel. 2023-04-28T04:45:28.764941+08:00 0 [Warning] [MY-010539] [Repl] Recovery from source pos 331385952 and file mysql-binlog.000008 for channel ''. Previous relay log pos and relay log file had been set to 471564, /data/mysql8.0/log/3399/relaylog/mysql-relay.000024 respectively. 2023-04-28T04:45:28.766286+08:00 5 [Warning] [MY-010897] [Repl] Storing MySQL user name or password information in the connection metadata repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START REPLICA; see the 'START REPLICA Syntax' in the MySQL Manual for more information. 2023-04-28T04:45:28.768944+08:00 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /tmp/mysqlx.sock 2023-04-28T04:45:28.769380+08:00 0 [System] [MY-010931] [Server] /data/mysql8.0/app/mysql/bin/mysqld: ready for connections. Version: '8.0.33' socket: '/data/mysql8.0/data/3399/mysql.sock' port: 3399 MySQL Community Server - GPL. 2023-04-28T04:45:28.769575+08:00 5 [System] [MY-014002] [Repl] Replica receiver thread for channel '': connected to source 'rep_user@134.178.223.26:3399' with server_uuid=426ac43a-e1a7-11ed-be36-fa163e6a97d1, server_id=33991. Starting GTID-based replication.
[28 Apr 2023 2:23]
huifa huang
mysql8.0.33-error.err
Attachment: mysql-error.err (application/octet-stream, text), 1.53 MiB.