Bug #71775 crashe : semaphore wait has lasted
Submitted: 20 Feb 2014 5:03 Modified: 8 Aug 2018 11:34
Reporter: kazu ishibash Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.6.10 OS:Linux (CentOS 6.2 (2.6.32-220.2.1.el6.x86_64))
Assigned to: CPU Architecture:Any
Tags: semaphore wait has lasted > 600 seconds

[20 Feb 2014 5:03] kazu ishibash
Description:
MySQL server crash.

InnoDB: Error: semaphore wait has lasted > 600 seconds

The information I got on the error log is as follows: 
---------------------------------------------
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.
2014-02-18 12:31:37 7f51c2a54700  InnoDB: Assertion failure in thread 139989134690048 in file srv0srv.cc line 1738
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/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
03:31:37 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=16
max_threads=151
thread_count=8
connection_count=8
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 184184 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

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 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x8bfd45]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x65b074]
/lib64/libpthread.so.0(+0xf4a0)[0x7f51f58ab4a0]
/lib64/libc.so.6(gsignal+0x35)[0x7f51f4549885]
/lib64/libc.so.6(abort+0x175)[0x7f51f454b065]
/usr/sbin/mysqld[0x98a7fc]
/lib64/libpthread.so.0(+0x77f1)[0x7f51f58a37f1]
/lib64/libc.so.6(clone+0x6d)[0x7f51f45fc92d]
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.
140218 12:31:38 mysqld_safe Number of processes running now: 0
140218 12:31:38 mysqld_safe mysqld restarted
2014-02-18 12:31:39 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-02-18 12:31:39 709 [Warning] You need to use --log-bin to make --binlog-format work.
2014-02-18 12:31:39 709 [Note] Plugin 'FEDERATED' is disabled.
2014-02-18 12:31:40 709 [Note] InnoDB: The InnoDB memory heap is disabled
2014-02-18 12:31:40 709 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-02-18 12:31:40 709 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-02-18 12:31:40 709 [Note] InnoDB: CPU does not support crc32 instructions
2014-02-18 12:31:40 709 [Note] InnoDB: Using Linux native AIO
2014-02-18 12:31:40 709 [Note] InnoDB: Initializing buffer pool, size = 512.0M
2014-02-18 12:31:40 709 [Note] InnoDB: Completed initialization of buffer pool
2014-02-18 12:31:40 709 [Note] InnoDB: Highest supported file format is Barracuda.
2014-02-18 12:31:40 709 [Note] InnoDB: Log scan progressed past the checkpoint lsn 3675849477956
2014-02-18 12:31:40 709 [Note] InnoDB: Database was not shutdown normally!
2014-02-18 12:31:40 709 [Note] InnoDB: Starting crash recovery.
2014-02-18 12:31:40 709 [Note] InnoDB: Reading tablespace information from the .ibd files...
2014-02-18 12:31:50 709 [Note] InnoDB: Restoring possible half-written data pages 
2014-02-18 12:31:50 709 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 3675854264597
InnoDB: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 16891 row operations to undo
InnoDB: Trx id counter is 51748352
2014-02-18 12:31:54 709 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 52930946, file name mysql-bin.000048
2014-02-18 12:32:04 709 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2014-02-18 12:32:04 7f5c26ddb700  InnoDB: Rolling back trx with id 51747714, 10591 rows to undo

InnoDB: Progress in percents: 12014-02-18 12:32:04 709 [Note] InnoDB: Waiting for purge to start
 2 32014-02-18 12:32:04 709 [Note] InnoDB: 1.2.10 started; log sequence number 3675854264597
 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 592014-02-18 12:32:04 709 [Note] Server hostname (bind-address): '*'; port: 3306
 602014-02-18 12:32:04 709 [Note] IPv6 is not available.
2014-02-18 12:32:04 709 [Note]   - '0.0.0.0' resolves to '0.0.0.0';
2014-02-18 12:32:04 709 [Note] Server socket created on IP: '0.0.0.0'.
 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002014-02-18 12:32:04 709 [Note] InnoDB: Rollback of trx with id 51747714 completed
2014-02-18 12:32:04 7f5c26ddb700  InnoDB: Rolling back trx with id 51747693, 6300 rows to undo

InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 1002014-02-18 12:32:04 709 [Note] InnoDB: Rollback of trx with id 51747693 completed
2014-02-18 12:32:04 7f5c26ddb700  InnoDB: Rollback of non-prepared transactions completed
2014-02-18 12:32:04 709 [Note] Event Scheduler: Loaded 0 events
2014-02-18 12:32:04 709 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.10-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
---------------------------------------------

Please let me know the cause which crash generated. 

How to repeat:
Unknown
[20 Feb 2014 9:45] Shane Bester
Please upload complete mysql error log so we can see the innodb status printouts.
5.6.16 is the current version, so you're encouraged to try that too.
[21 Feb 2014 1:12] kazu ishibash
The following file names 
・mysql-bug-71775.zip

Please see a log.
[4 Mar 2014 4:43] David David
Exactly the same incident happened in my environment. Any thoughts from the developers?
[14 Apr 2016 6:23] monty solomon
May be a duplicate of 73890
[8 Aug 2018 11:34] Miguel Solorzano
There isn't a repeatable test case here, please check with latest releases. Thanks.