MySQL Bugs: #26834: MySQL crashes with "long semaphore wait"

Bug #26834	MySQL crashes with "long semaphore wait"
Submitted:	5 Mar 2007 7:07	Modified:	24 Aug 2007 0:13
Reporter:	Philip Blatter	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.0.32	OS:	Linux (Linux (Debian Sarge))
Assigned to:		CPU Architecture:	Any

Description:
Since about 3 weeks, our production database server crashes twice every night. It's possible to restart running jobs next day, but i don't know whats getting corrupted due to mysql daemon crash...

-- first message in error log: --
Mar  2 21:33:10 sdm-core mysqld[4434]: InnoDB: Warning: a long semaphore wait:
Mar  2 21:33:10 sdm-core mysqld[4434]: --Thread 456428464 has waited at ../include/btr0btr.ic line 28 for 241.00 seconds the semaphore:
Mar  2 21:33:10 sdm-core mysqld[4434]: X-lock on RW-latch at 0x2fc57ee4 created in file buf0buf.c line 497
Mar  2 21:33:10 sdm-core mysqld[4434]: a writer (thread id 456428464) has reserved it in mode  wait exclusive
Mar  2 21:33:10 sdm-core mysqld[4434]: number of readers 1, waiters flag 1
Mar  2 21:33:10 sdm-core mysqld[4434]: Last time read locked in file btr0sea.c line 765
Mar  2 21:33:10 sdm-core mysqld[4434]: Last time write locked in file btr0pcur.c line 247
Mar  2 21:33:10 sdm-core mysqld[4434]: InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
Mar  2 21:33:10 sdm-core mysqld[4434]: InnoDB: Pending preads 0, pwrites 1

-- after many times, mysql prints InnoDB Monitor output to syslog, mysql crashes with following messages: --

Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: ###### Diagnostic info printed to the standard error stream
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: Error: semaphore wait has lasted > 600 seconds
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: We intentionally crash the server, because it appears to be hung.
Mar  2 21:42:44 sdm-core mysqld[4434]: 070302 21:42:44InnoDB: Assertion failure in thread 501685168 in file srv0srv.c line 2093
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: We intentionally generate a memory trap.
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: If you get repeated assertion failures or crashes, even
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: immediately after the mysqld startup, there may be
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: corruption in the InnoDB tablespace. Please refer to
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
Mar  2 21:42:44 sdm-core mysqld[4434]: InnoDB: about forcing recovery.
Mar  2 21:42:44 sdm-core mysqld[4434]: mysqld got signal 11;
Mar  2 21:42:44 sdm-core mysqld[4434]: This could be because you hit a bug. It is also possible that this binary
Mar  2 21:42:44 sdm-core mysqld[4434]: or one of the libraries it was linked against is corrupt, improperly built,
Mar  2 21:42:44 sdm-core mysqld[4434]: or misconfigured. This error can also be caused by malfunctioning hardware.
Mar  2 21:42:44 sdm-core mysqld[4434]: We will try our best to scrape up some info that will hopefully help diagnose
Mar  2 21:42:44 sdm-core mysqld[4434]: the problem, but since we have already crashed, something is definitely wrong
Mar  2 21:42:44 sdm-core mysqld[4434]: and this may fail.
Mar  2 21:42:44 sdm-core mysqld[4434]:
Mar  2 21:42:44 sdm-core mysqld[4434]: key_buffer_size=1073741824
Mar  2 21:42:44 sdm-core mysqld[4434]: read_buffer_size=131072
Mar  2 21:42:44 sdm-core mysqld[4434]: max_used_connections=769
Mar  2 21:42:44 sdm-core mysqld[4434]: max_connections=1000
Mar  2 21:42:44 sdm-core mysqld[4434]: threads_connected=769
Mar  2 21:42:44 sdm-core mysqld[4434]: It is possible that mysqld could use up to
Mar  2 21:42:44 sdm-core mysqld[4434]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 3224568 K
Mar  2 21:42:44 sdm-core mysqld[4434]: bytes of memory
Mar  2 21:42:44 sdm-core mysqld[4434]: Hope that's ok; if not, decrease some variables in the equation.
Mar  2 21:42:44 sdm-core mysqld[4434]:
Mar  2 21:42:44 sdm-core mysqld[4434]: You seem to be running 32-bit Linux and have 769 concurrent connections.
Mar  2 21:42:44 sdm-core mysqld[4434]: If you have not changed STACK_SIZE in LinuxThreads and built the binary
Mar  2 21:42:44 sdm-core mysqld[4434]: yourself, LinuxThreads is quite likely to steal a part of the global heap for
Mar  2 21:42:44 sdm-core mysqld[4434]: the thread stack. Please read http://www.mysql.com/doc/en/Linux.html
Mar  2 21:42:44 sdm-core mysqld[4434]:
Mar  2 21:42:44 sdm-core mysqld[4434]: thd=(nil)
Mar  2 21:42:44 sdm-core mysqld[4434]: Attempting backtrace. You can use the following information to find out
Mar  2 21:42:44 sdm-core mysqld[4434]: where mysqld died. If you see no messages after this, something went
Mar  2 21:42:44 sdm-core mysqld[4434]: terribly wrong...
Mar  2 21:42:44 sdm-core mysqld[4434]: Cannot determine thread, fp=0x1de71788, backtrace may not be correct.
Mar  2 21:42:44 sdm-core mysqld[4434]: Stack range sanity check OK, backtrace follows:
Mar  2 21:42:44 sdm-core mysqld[4434]: 0x81c1565
Mar  2 21:42:44 sdm-core mysqld[4434]: 0x82f0db3
Mar  2 21:42:44 sdm-core mysqld[4434]: 0xb7fa1b63
Mar  2 21:42:44 sdm-core mysqld[4434]: 0xb7e1918a
Mar  2 21:42:44 sdm-core mysqld[4434]: New value of fp=(nil) failed sanity check, terminating stack trace!
Mar  2 21:42:44 sdm-core mysqld[4434]: Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
Mar  2 21:42:44 sdm-core mysqld[4434]: stack trace is much more helpful in diagnosing the problem, so please do
Mar  2 21:42:44 sdm-core mysqld[4434]: resolve it
Mar  2 21:42:44 sdm-core mysqld[4434]: The manual page at http://www.mysql.com/doc/en/Crashing.html contains
Mar  2 21:42:44 sdm-core mysqld[4434]: information that should help you find out what is causing the crash.

-- then it gets restarted by mysqld_safe and starts crash recovery: --

Mar  2 21:43:45 sdm-core mysqld[6485]: 070302 21:43:45  InnoDB: Database was not shut down normally!
Mar  2 21:43:45 sdm-core mysqld[6485]: InnoDB: Starting crash recovery.
Mar  2 21:43:45 sdm-core mysqld[6485]: InnoDB: Reading tablespace information from the .ibd files...
Mar  2 21:43:45 sdm-core mysqld[6485]: InnoDB: Restoring possible half-written data pages from the doublewrite
Mar  2 21:43:45 sdm-core mysqld[6485]: InnoDB: buffer...
Mar  2 21:43:46 sdm-core mysqld[6485]: 070302 21:43:46  InnoDB: Starting log scan based on checkpoint at
Mar  2 21:43:46 sdm-core mysqld[6485]: InnoDB: log sequence number 298 3056455081.
Mar  2 21:43:46 sdm-core mysqld[6485]: InnoDB: Doing recovery: scanned up to log sequence number 298 3056672351
Mar  2 21:43:46 sdm-core mysqld[6485]: 070302 21:43:46  InnoDB: Starting an apply batch of log records to the database...
Mar  2 21:43:47 sdm-core mysqld[6485]: InnoDB: Progress in percents: 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
Mar  2 21:43:47 sdm-core mysqld[6485]: InnoDB: Apply batch completed
Mar  2 21:43:47 sdm-core mysqld[6485]: 070302 21:43:47  InnoDB: Started; log sequence number 298 3056672351
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 950109184 bytes)
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 712581120 bytes)
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 534435840 bytes)
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 400825344 bytes)
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 300616704 bytes)
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 225460224 bytes)
Mar  2 21:43:47 sdm-core mysqld[6485]: ^G/usr/sbin/mysqld: Out of memory (Needed 169095168 bytes)
Mar  2 21:43:48 sdm-core mysqld[6485]: 070302 21:43:48 [Note] /usr/sbin/mysqld: ready for connections.

--
I don't know, if mysqld reported "Out of memory" before we had this problem, but system has 7G of memory. 2715932k free + 1371416k cached after mysql is started up and running.

How to repeat:
Easily repeatable on my system, since it crashes every night. Unfortunately i don't have an idea which exact statements cause the crash, because all statements running are executed thousand times all over the day.

Thank you for a problem report. It looks like a duplicate of a known bug, bug #25645. Please, check.

> Linux db01 2.6.19 #1 SMP Tue Dec 12 15:59:57 CET 2006 i686 GNU/Linux

We are on 32bit Linux. So i don't think its a duplicate.

Please, send your my.cnf file content then. On 32-bit Linux < 3G of memory is available for mysqld process...

[mysqld]
old_passwords = true # inserted by debconf
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
language = /usr/share/mysql/english
max_connections = 1000
table_cache = 2048
tmp_table_size = 64M
skip-external-locking
bind-address = 127.0.0.1
key_buffer = 1G
max_allowed_packet = 128M
thread_stack = 128K
query_cache_limit = 2M
query_cache_size = 64M
query_cache_type = 1
log-slow-queries = /var/log/mysql/mysql-slow.log
skip-bdb
innodb_data_home_dir = /ibdata
innodb_data_file_path = ibdata1:200Graw
set-variable = innodb_buffer_pool_size=2G
set-variable = innodb_additional_mem_pool_size=16M
innodb_log_group_home_dir = /iblogs
innodb_log_arch_dir = /iblogs
innodb_log_archive = 0
set-variable = innodb_log_files_in_group=3
set-variable = innodb_log_file_size=1G
set-variable = innodb_log_buffer_size=200M
innodb_flush_log_at_trx_commit=1
set-variable = innodb_file_io_threads=4
set-variable = innodb_lock_wait_timeout=300

This is almost surely just out of memory issue then. Please, try to set:

set-variable = innodb_buffer_pool_size=1G

and check if it will influence crashes in any way.

Philip,

please attach the entire .err log, gzipped.

I agree withn Valeriy that this might be an out-of-memory problem.

Regards,

Heikki

Error log has been attached.

After setting the cache to a smaller value, the server didn't crash anymore. BUT: InnoDB prints status messages to error log - just the same as before crashing.

Looks like that output in the log is either a feature of your '5.0.32-Dotdeb_1.dotdeb.1-log' version (formally not supported by MySQL yet), or somebody/some cron job just started to execute SHOW INNODB STATUS several times based on some reason. 

Anyway, your crash looks like out-of-memory issue based on results with smaller innodb_buffer_pool_size. I think, this is not a bug.

See bug #25645 which probably fixes this, fix is in 5.0.48 and 5.1.21.