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

Bug #26834	MySQL crashes with "long semaphore wait"
Submitted:	5 Mar 2007 8:07	Modified:	24 Aug 2007 2:13
Reporter:	Philip Blatter
Status:	Duplicate
Category:	Server: InnoDB	Severity:	S2 (Serious)
Version:	5.0.32	OS:	Linux (Linux (Debian Sarge))
Assigned to:		Target Version:

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.