MySQL Bugs: #63245: Mysqld crashes

Bug #63245	Mysqld crashes
Submitted:	14 Nov 2011 11:33	Modified:	14 Nov 2011 16:32
Reporter:	Turgut Kalfaoglu	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Installing	Severity:	S1 (Critical)
Version:	5.5.17	OS:	Linux (centos 5)
Assigned to:		CPU Architecture:	Any
Tags:	crash

Description:
Server started crashing after an upgrade from mysql-5.1.59-2.el5.art
 to 5.5.17-2.el5.art 
Unfortunately downgrading back did not help, the crashes continued.

The crashes started happening about 24 hours after the upgrade.

How to repeat:
it repeats by itself - its a production machine too..

Latest crash log:
Version: '5.1.59-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution
111114 13:30:59 - mysqld got signal 11 ;
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=1048576
read_buffer_size=1048576
max_used_connections=3
max_threads=151
threads_connected=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 311833 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x19bad8a0
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 = 0x46271ef8 thread_stack 0x40000
Fatal signal 6 while backtracing
111114 13:31:00 mysqld_safe Number of processes running now: 0
111114 13:31:00 mysqld_safe mysqld restarted
111114 13:31:00 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_file'' instead.
111114 13:31:00 [Note] Plugin 'ndbcluster' is disabled.
111114 13:31:00  InnoDB: Initializing buffer pool, size = 8.0M
111114 13:31:00  InnoDB: Completed initialization of buffer pool
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
111114 13:31:00  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
111114 13:31:00  InnoDB: Started; log sequence number 3 2933980358
111114 13:31:00 [Note] Event Scheduler: Loaded 0 events
111114 13:31:00 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.59-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution
111114 13:31:07 - mysqld got signal 11 ;
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=1048576
read_buffer_size=1048576
max_used_connections=8
max_threads=151
threads_connected=8
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 311833 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x17cc1270
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 = (nil) thread_stack 0x40000
Fatal signal 6 while backtracing
111114 13:31:07 mysqld_safe Number of processes running now: 0
111114 13:31:07 mysqld_safe mysqld restarted
111114 13:31:07 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_file'' instead.
111114 13:31:07 [Note] Plugin 'ndbcluster' is disabled.
111114 13:31:07  InnoDB: Initializing buffer pool, size = 8.0M
111114 13:31:07  InnoDB: Completed initialization of buffer pool
InnoDB: Log scan progressed past the checkpoint lsn 3 2933980358
111114 13:31:07  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 3 2933980858
111114 13:31:07  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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
111114 13:31:07  InnoDB: Started; log sequence number 3 2933980858
111114 13:31:07 [Note] Event Scheduler: Loaded 0 events
111114 13:31:07 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.59-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution
111114 13:31:17 - mysqld got signal 11 ;
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=1048576
read_buffer_size=1048576
max_used_connections=5
max_threads=151
threads_connected=3
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 311833 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x3fa89e0
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 = (nil) thread_stack 0x40000
/usr/libexec/mysqld(my_print_stacktrace+0x24) [0x9416c4]
/usr/libexec/mysqld(handle_segfault+0x367) [0x60c427]
/lib64/libpthread.so.0 [0x3dc340eb70]
/usr/libexec/mysqld(row_mysql_store_blob_ref+0x40) [0x835200]
/usr/libexec/mysqld [0x8403b0]
/usr/libexec/mysqld(row_search_for_mysql+0x2f5e) [0x845c4e]
111114 13:31:17 mysqld_safe Number of processes running now: 0
111114 13:31:17 mysqld_safe mysqld restarted
111114 13:31:17 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_file'' instead.
111114 13:31:17 [Note] Plugin 'ndbcluster' is disabled.
111114 13:31:17  InnoDB: Initializing buffer pool, size = 8.0M
111114 13:31:17  InnoDB: Completed initialization of buffer pool
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
111114 13:31:17  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
111114 13:31:17  InnoDB: Started; log sequence number 3 2933980942
111114 13:31:17 [Note] Event Scheduler: Loaded 0 events
111114 13:31:17 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.59-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  Source distribution
[root@panel ~] #  *** glibc detected *** /usr/libexec/mysqld: malloc(): memory corruption: 0x0000000008172340 ***
======= Backtrace: =========
/lib64/libc.so.6[0x3dc2c730fe]
/lib64/libc.so.6(__libc_malloc+0x6e)[0x3dc2c74e2e]
/lib64/libc.so.6(__backtrace_symbols+0x104)[0x3dc2ce6964]
/usr/libexec/mysqld(my_print_stacktrace+0x55)[0x9416f5]
/usr/libexec/mysqld(handle_segfault+0x367)[0x60c427]
/lib64/libpthread.so.0[0x3dc340eb70]
/usr/libexec/mysqld(row_mysql_store_blob_ref+0x40)[0x835200]
/usr/libexec/mysqld[0x8403b0]
/usr/libexec/mysqld(row_search_for_mysql+0x2f5e)[0x845c4e]
/usr/libexec/mysqld(_ZN11ha_innobase10index_readEPhPKhj16ha_rkey_function+0x1d3)[0x7b4303]
/usr/libexec/mysqld(_ZN11ha_innobase11index_firstEPh+0x37)[0x7b21c7]
/usr/libexec/mysqld(_ZN11ha_innobase8rnd_nextEPh+0x37)[0x7b3ba7]
/usr/libexec/mysqld(_Z13rr_sequentialP11READ_RECORD+0

Suggested fix:
dont know.

I have since upgraded back to 5.5 since it apparently does not help to downgrade anyway. I have done mysqlcheck auto-repair check-upgrade as well.. did not help.

during the same centos "yum update" run, the following files were also changed:

ov 12 22:37:04 panel yum: Erased: tzdata
Nov 12 22:37:08 panel yum: Erased: kernel-devel
Nov 12 22:37:14 panel yum: Erased: tzdata-java
Nov 12 22:37:20 panel yum: Erased: clamd
Nov 12 22:37:21 panel yum: Erased: e2fsprogs-libs
Nov 12 22:37:23 panel yum: Erased: libX11
Nov 12 22:37:28 panel yum: Erased: cpp
Nov 12 22:37:29 panel yum: Erased: libxml2
Nov 12 22:37:29 panel yum: Erased: openssl
Nov 12 22:37:29 panel yum: Erased: selinux-policy
Nov 12 22:37:32 panel yum: Erased: nspr
Nov 12 22:37:32 panel yum: Erased: device-mapper
Nov 12 22:37:33 panel yum: Erased: libgcj
Nov 12 22:37:34 panel yum: Erased: libsmbclient
Nov 12 22:37:34 panel yum: Erased: nspr-devel
Nov 12 22:37:35 panel yum: Erased: samba-client
Nov 12 22:37:35 panel yum: Erased: popt
Nov 12 22:37:35 panel yum: Erased: procps
Nov 12 22:37:36 panel yum: Erased: udev
Nov 12 22:37:37 panel yum: Erased: nscd
Nov 12 22:37:37 panel yum: Erased: nss
Nov 12 22:37:37 panel yum: Erased: postgresql-libs
Nov 12 22:37:38 panel yum: Erased: kpartx
Nov 12 22:37:38 panel yum: Erased: centos-release-notes
Nov 12 22:37:38 panel yum: Erased: pam_krb5
Nov 12 22:37:39 panel yum: Erased: krb5-libs
Nov 12 22:37:40 panel yum: Erased: java-1.6.0-openjdk
Nov 12 22:37:45 panel yum: Erased: libgfortran
Nov 12 22:37:45 panel yum: Erased: nash
Nov 12 22:37:45 panel yum: Erased: boost
Nov 12 22:37:46 panel yum: Erased: ecryptfs-utils
Nov 12 22:37:48 panel yum: Erased: logrotate
Nov 12 22:37:48 panel yum: Erased: libstdc++
Nov 12 22:37:48 panel yum: Erased: clamav-db
Nov 12 22:37:49 panel yum: Erased: coreutils
Nov 12 22:37:50 panel yum: Erased: lvm2
Nov 12 22:37:51 panel yum: Erased: samba-common
Nov 12 22:37:52 panel yum: Erased: libgcc
Nov 12 22:37:52 panel yum: Erased: net-snmp-libs
Nov 12 22:37:52 panel yum: Erased: curl
Nov 12 22:37:52 panel yum: Erased: ghostscript
Nov 12 22:37:54 panel yum: Erased: device-mapper-multipath
Nov 12 22:37:54 panel yum: Erased: xorg-x11-server-Xnest
Nov 12 22:37:54 panel yum: Erased: e2fsprogs
Nov 12 22:37:54 panel yum: Erased: libvolume_id
Nov 12 22:37:54 panel yum: Erased: SysVinit
Nov 12 22:37:55 panel yum: Erased: bash
Nov 12 22:37:56 panel yum: Erased: e2fsprogs-devel
Nov 12 22:43:14 panel yum: Updated: libxml2-2.6.26-2.1.12.el5_7.1.x86_64
Nov 12 22:43:17 panel yum: Updated: nss-3.12.10-7.el5_7.x86_64
Nov 12 22:43:22 panel yum: Updated: mysql-libs-5.5.17-2.el5.art.x86_64
Nov 12 22:43:29 panel yum: Updated: mysql-5.5.17-2.el5.art.x86_64
Nov 12 22:43:30 panel yum: Updated: freetype-2.2.1-28.el5_7.1.x86_64
Nov 12 22:43:32 panel yum: Updated: xulrunner-1.9.2.24-2.el5_7.x86_64
Nov 12 22:43:34 panel yum: Updated: nss_ldap-253-42.el5_7.4.x86_64
Nov 12 22:43:42 panel yum: Updated: mysql-server-5.5.17-2.el5.art.x86_64
Nov 12 22:43:44 panel yum: Updated: nss-tools-3.12.10-7.el5_7.x86_64
Nov 12 22:43:45 panel yum: Updated: libxml2-python-2.6.26-2.1.12.el5_7.1.x86_64
Nov 12 22:43:48 panel yum: Updated: 1:autofs-5.0.1-0.rc2.156.el5_7.4.x86_64
Nov 12 22:43:48 panel yum: Updated: rsh-0.17-40.el5_7.1.x86_64
Nov 12 22:43:48 panel yum: Updated: mysql-bench-5.5.17-2.el5.art.x86_64
Nov 12 22:43:49 panel yum: Updated: nss-devel-3.12.10-7.el5_7.x86_64
Nov 12 22:43:52 panel yum: Updated: libxml2-devel-2.6.26-2.1.12.el5_7.1.x86_64
Nov 12 22:43:56 panel yum: Updated: tzdata-java-2011l-4.el5.x86_64
Nov 12 22:44:04 panel yum: Updated: tzdata-2011l-4.el5.x86_64
Nov 12 22:44:04 panel yum: Updated: atomic-release-1.0-14.el5.art.noarch
Nov 12 22:44:05 panel yum: Updated: mysql-libs-5.5.17-2.el5.art.i386
Nov 12 22:44:08 panel yum: Updated: libxml2-2.6.26-2.1.12.el5_7.1.i386
Nov 12 22:44:09 panel yum: Updated: freetype-2.2.1-28.el5_7.1.i386
Nov 12 22:44:12 panel yum: Updated: nss-3.12.10-7.el5_7.i386
Nov 12 22:44:13 panel yum: Updated: nss_ldap-253-42.el5_7.4.i386
Nov 12 22:44:14 panel yum: Updated: mysql-devel-5.5.17-2.el5.art.i386
Nov 12 22:44:19 panel yum: Updated: libxml2-devel-2.6.26-2.1.12.el5_7.1.i386
Nov 12 22:44:20 panel yum: Updated: mysql-5.5.17-2.el5.art.i386

It should not crash of course, but a 8M 'innodb_buffer_pool_size' setting is very low.  As far as I remember the default was 8M earlier but now much higher (I don't remember if it was changed between 5.0 and 5.1 or between 5.1 and 5.5).

On a prodcutions server the settign should be much higher (at least if you use InnoDB as the primary engine).  Sone recommendations say up to 50% of available memory - even though I personally think in most scenarios it will make little difference if you have 256M or more. And the bigger the setting the slower InnoDB crash recovery. For that reason other recommendations say not bigger than 1G.

Refer for instance:
http://www.cowboycoded.com/2009/08/26/a-quick-performance-tune-for-mysql-innodb_buffer_poo...
http://www.mysqlperformanceblog.com/2007/11/03/choosing-innodb_buffer_pool_size/

Maybe MySQL 5.5 does not like such low setting. I cannot explain why 'downgrading' to 5.1 continues the problem though.

Anyway I would try to reaise this setting.  Even if it does not help the crash it will increase performance. 

Peter
(not a MySQL person).

Thanks - I updated my.cnf, which looks like this now, but it did not help, it still crashes a lot.

[mysqld]

datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql

old_passwords=1

log-error=/var/log/mysql-error.log

query_cache_type=1
query_cache_limit=1M
query_cache_size=2M

log_slow_queries=/var/log/mysqld.slow.log

thread_concurrency=2
thread_cache_size=20
key_buffer=1M
sort_buffer_size=1M
read_buffer_size=1M
read_rnd_buffer_size=768K
innodb_buffer_pool_size = 256M

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

SOLVED: A corrupt database was crashing Mysqld every time. 
Would the admins be interested in the database to ensure that future Mysql's do not crash with such bad data?

if the problem was a corrupted page or innodb table, then see:

http://bugs.mysql.com/bug.php?id=10132
(Crashing the server on corrupt InnoDB page is unhelpful)