Bug #64873 Error: semaphore wait has lasted > 600 seconds
Submitted: 5 Apr 2012 10:51 Modified: 24 Jan 2014 14:31
Reporter: Ruben Gaspar Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5.20 OS:Linux (rhel 5: 2.6.18-274.7.1.el5)
Assigned to: CPU Architecture:Any
Tags: InnoDB: Assertion failure, long wait, smaphore, srv0srv.c, X-lock

[5 Apr 2012 10:51] Ruben Gaspar
Description:
While trying to execute these two statements the server crashed: 
+++ 
use stomanin_dev; 
DELETE FROM cache_bootstrap 
WHERE (cid = 'bootstrap_modules') 
DELETE FROM cache_bootstrap 
WHERE (cid = 'system_list') 
+++ 

while updating the index linked to expire column. 

This table is related to a drupal site.
The information I got on the error log is as follows: 

+++ 
InnoDB: error in sec index entry update in 
InnoDB: index "expire" of table "stomanin_dev"."cache_bootstrap" 
InnoDB: tuple DATA TUPLE: 2 fields; 
0: len 4; hex 80000000; asc ;; 
1: len 17; hex 626f6f7473747261705f6d6f64756c6573; asc bootstrap_modules;; 

InnoDB: record PHYSICAL RECORD: n_fields 1; compact format; info bits 0 
0: len 8; hex 696e66696d756d00; asc infimum ;; 

TRANSACTION 2B7810B8, ACTIVE 0 sec updating or deleting 
mysql tables in use 1, locked 1 
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1 
MySQL thread id 10744775, OS thread handle 0x4a1e5940, query id 1627513742 drupalfe08.cern.ch 137.138.76.37 stomanin_dev updating
 DELETE FROM cache_bootstrap 
WHERE (cid = 'bootstrap_modules') 

InnoDB: Submit a detailed bug report to http://bugs.mysql.com 
InnoDB: error in sec index entry update in 
InnoDB: index "expire" of table "stomanin_dev"."cache_bootstrap" 
InnoDB: tuple DATA TUPLE: 2 fields; 
0: len 4; hex 80000000; asc ;; 
1: len 11; hex 73797374656d5f6c697374; asc system_list;; 

InnoDB: record PHYSICAL RECORD: n_fields 1; compact format; info bits 0 
0: len 8; hex 696e66696d756d00; asc infimum ;; 

TRANSACTION 2B7810D1, ACTIVE 0 sec updating or deleting 
mysql tables in use 1, locked 1 
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1 
MySQL thread id 10744775, OS thread handle 0x4a1e5940, query id 1627513804 drupalfe08.cern.ch 137.138.76.37 stomanin_dev updating
 DELETE FROM cache_bootstrap 
WHERE (cid = 'system_list') 

InnoDB: Submit a detailed bug report to http://bugs.mysql.com 
InnoDB: Warning: a long semaphore wait: 
--Thread 1237379392 has waited at row0upd.c line 2131 for 241.00 seconds the semaphore:
 X-lock (wait_ex) on RW-latch at 0x2aab07cbb6c0 created in file buf0buf.c line 907
 a writer (thread id 1237379392) has reserved it in mode wait exclusive 
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff 
Last time read locked in file row0sel.c line 3090 
Last time write locked in file /export/home/pb2/build/sb_0-4575859-1324065297.24/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/row/row0upd.c line 2131
 InnoDB: Warning: a long semaphore wait: 
--Thread 1241639232 has waited at btr0cur.c line 253 for 241.00 seconds the semaphore:
 S-lock on RW-latch at 0x2aab07cbb6c0 created in file buf0buf.c line 907 
a writer (thread id 1237379392) has reserved it in mode wait exclusive 
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff 
Last time read locked in file row0sel.c line 3090 
Last time write locked in file /export/home/pb2/build/sb_0-4575859-1324065297.24/rpm/BUILD/mysql-5.5.20/mysql-5.5.20/storage/innobase/row/row0upd.c line 2131
 InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info: 
InnoDB: Pending preads 0, pwrites 0 

+++ 

Due to the long semaphore wait the sever reboots: 

+++ 
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. 
120330 2:54:30 InnoDB: Assertion failure in thread 1219701056 in file srv0srv.c line 2454
 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.5/en/forcing-innodb-recovery.html 
InnoDB: about forcing recovery. 
00:54:30 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. 
... 

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)[0x7d08c5] 
/usr/sbin/mysqld(handle_fatal_signal+0x3e1)[0x689381] 
/lib64/libpthread.so.0[0x34a040eb70] 
/lib64/libc.so.6(gsignal+0x35)[0x349fc30265] 
/lib64/libc.so.6(abort+0x110)[0x349fc31d10] 
/usr/sbin/mysqld[0x80ffc4] 
/lib64/libpthread.so.0[0x34a040673d] 
/lib64/libc.so.6(clone+0x6d)[0x349fcd44bd] 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains 

Please let us know if you would like more evidences.

How to repeat:
The crashed repeated three days after:

Version: '5.5.20-log'  socket: '/var/lib/mysql/mysql.sock'  port: 5500  MySQL Community Server (GPL)
InnoDB: Warning: a long semaphore wait:
--Thread 1250027840 has waited at fsp0fsp.c line 1916 for 241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x2aab07155740 created in file buf0buf.c line 907
...
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)[0x7d08c5]
/usr/sbin/mysqld(handle_fatal_signal+0x3e1)[0x689381]
/lib64/libpthread.so.0[0x34a040eb70]
/lib64/libc.so.6(gsignal+0x35)[0x349fc30265]
/lib64/libc.so.6(abort+0x110)[0x349fc31d10]
/usr/sbin/mysqld[0x80ffc4]
/lib64/libpthread.so.0[0x34a040673d]
/lib64/libc.so.6(clone+0x6d)[0x349fcd44bd]
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.

I will be happy to upload the err log file. Or any further information.

First crash was on friday 30th March at around 2:50am (CET) and second one was on Monday 2nd April at around 21:40 (CET)
[5 Apr 2012 10:54] Ruben Gaspar
This is my.cnf file:
[mysqld]
port=5500
socket=/var/lib/mysql/mysql.sock
datadir=/ORA/dbs03/DRUPAL/mysql
log-bin=/ORA/dbs02/DRUPAL/mysql/binlog
expire_logs_days=5
binlog_format=MIXED
general-log-file=/ORA/dbs03/DRUPAL/mysql/mysql.log
#Control when binary logs are rotated
max_binlog_size=1073741824
#IO Power
innodb_read_io_thread=4
innodb_write_io_threads=4
innodb_io_capacity=200
# server-id=2 - on the slave!
server-id=1
# consider setting to 2 to improve performance, 0 for extreme (not ACIDcompliant):
innodb_flush_log_at_trx_commit=1
sync_binlog=1
innodb_file_per_table
innodb_log_file_size=16M
# additionally on slave if needed:
log-slave-updates
innodb_flush_method=O_DIRECT
innodb_buffer_pool_size=5G
#enable performance schema
performance_schema
# logging
log_output=FILE
slow_query_log=1
slow_query_log_file=/ORA/dbs03/DRUPAL/mysql/slow_queries.log
# tuning:
max_connections=3000
max_user_connections=300
thread_cache_size=50
table_open_cache=6000
table_definition_cache=6000
query_cache_size=768M
key_buffer_size=256M
innodb_open_files=700
tmp_table_size=33554432
max_heap_table_size=33554432
max_allowed_packet=64M

The tables involved in first crash:
mysql> show create table stomanin_dev.cache_bootstrap;
| Table           | Create Table                                                                           | cache_bootstrap | CREATE TABLE `cache_bootstrap` (
  `cid` varchar(255) NOT NULL DEFAULT '' COMMENT 'Primary Key: Unique cache ID.',
  `data` longblob COMMENT 'A collection of data to cache.',
  `expire` int(11) NOT NULL DEFAULT '0' COMMENT 'A Unix timestamp indicating when the cache entry should expire, or 0 for never.',
  `created` int(11) NOT NULL DEFAULT '0' COMMENT 'A Unix timestamp indicating when the cache entry was created.',
  `serialized` smallint(6) NOT NULL DEFAULT '0' COMMENT 'A flag to indicate whether content is serialized (1) or not (0).',
  PRIMARY KEY (`cid`),
  KEY `expire` (`expire`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COMMENT='Cache table for data required to bootstrap Drupal, may be...' |

mysql> show indexes from cache_bootstrap from stomanin_dev; 
+-----------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
 +-----------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 | cache_bootstrap | 0 | PRIMARY | 1 | cid | A | 6 | NULL | NULL | | BTREE | | |
 | cache_bootstrap | 1 | expire | 1 | expire | A | 6 | NULL | NULL | | BTREE | | |
 +-----------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 2 rows in set (0.00 sec) 

Different tables were involved in second crash though the symptoms are exactly the same.

I upload my error file.
[9 Apr 2012 19:03] Ruben Gaspar
I have just uploaded the error log file of my mysql sever:
ftp> put mysqldrupal_dbvrtg4030_bug64873.zip
200 PORT command successful. Consider using PASV.
150 Ok to send data.
226 File receive OK.
ftp: 1048695 bytes sent in 1.98Seconds 530.98Kbytes/sec.

Thanks for your time.
[24 Dec 2013 14:31] Sveta Smirnova
Thank you for the report.

I am really sorry, but error log file got removed from our FTP server due to retention policy. Please re-upload and name file as described in the "Files" tab of the bug report page.

Also please note that long semaphore wait can happen in normal operations if table is locked for too much time. This usually happens during operations, such as CHECK TABLE of large table, but can also be affected by other locks.
[25 Jan 2014 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".