Bug #69291 mysql crashed ,restart mysql cant recovery
Submitted: 21 May 2013 4:08 Modified: 10 Jul 2013 19:03
Reporter: gust zhang Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: General Severity:S1 (Critical)
Version:5.6.11 OS:Linux (centos 6.2)
Assigned to: CPU Architecture:Any

[21 May 2013 4:08] gust zhang
Description:

130521 11:27:05 mysqld_safe Starting mysqld daemon with databases from /home/mysqlserver/62
2013-05-21 11:27:05 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-05-21 11:27:05 11796 [Note] Plugin 'FEDERATED' is disabled.
2013-05-21 11:27:05 11796 [Note] InnoDB: The InnoDB memory heap is disabled
2013-05-21 11:27:05 11796 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-05-21 11:27:05 11796 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-05-21 11:27:05 11796 [Note] InnoDB: Using Linux native AIO
2013-05-21 11:27:05 11796 [Note] InnoDB: Using CPU crc32 instructions
2013-05-21 11:27:05 11796 [Note] InnoDB: Initializing buffer pool, size = 3.0G
2013-05-21 11:27:06 11796 [Note] InnoDB: Completed initialization of buffer pool
2013-05-21 11:27:06 11796 [Note] InnoDB: Highest supported file format is Barracuda.
2013-05-21 11:27:07 11796 [Note] InnoDB: Log scan progressed past the checkpoint lsn 915136055978
2013-05-21 11:27:07 11796 [Note] InnoDB: Database was not shutdown normally!
2013-05-21 11:27:07 11796 [Note] InnoDB: Starting crash recovery.
2013-05-21 11:27:07 11796 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-05-21 11:27:07 11796 [Note] InnoDB: Restoring possible half-written data pages 
2013-05-21 11:27:07 11796 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 915141298688
InnoDB: Doing recovery: scanned up to log sequence number 915144880042
InnoDB: Transaction 768660351 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 768660736
2013-05-21 11:27:07 11796 [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 863301765, file name mysql-bin.000080
2013-05-21 11:27:10 11796 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: Starting in background the rollback of uncommitted transactions
2013-05-21 11:27:10 7fd695a01700  InnoDB: Rollback of non-prepared transactions completed
2013-05-21 11:27:10 11796 [Note] InnoDB: Waiting for purge to start
InnoDB: Dump of the tablespace extent descriptor:  len 40; hex 00000000001e4750000380000f26000400000d6e00000004aaaaaaaaaaaaaaaaaaaaaaaafafbfeef; asc       GP     &     n                    ;
InnoDB: Serious error! InnoDB is trying to free page 334003
InnoDB: though it is already marked as free in the tablespace!
InnoDB: The tablespace free space info is corrupt.
InnoDB: You may need to dump your InnoDB tables and recreate the whole
InnoDB: database!
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
2013-05-21 11:27:10 7fd6983e7700  InnoDB: Assertion failure in thread 140559653959424 in file fsp0fsp.cc line 3079
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:27:10 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=536870912
read_buffer_size=2097152
max_used_connections=0
max_threads=50
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 729764 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)[0x8c4655]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x65c004]
/lib64/libpthread.so.0[0x3af6a0f500]
/lib64/libc.so.6(gsignal+0x35)[0x3af66328a5]
/lib64/libc.so.6(abort+0x175)[0x3af6634085]
/usr/sbin/mysqld[0xab8ce5]
/usr/sbin/mysqld[0xab8e23]
/usr/sbin/mysqld[0xa586a0]
/usr/sbin/mysqld[0x9fbc58]
/usr/sbin/mysqld[0x9fcaba]
/usr/sbin/mysqld[0x9cd956]
/usr/sbin/mysqld[0xa254bb]
/usr/sbin/mysqld[0xa15e8f]
/lib64/libpthread.so.0[0x3af6a07851]
/lib64/libc.so.6(clone+0x6d)[0x3af66e890d]
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.
130521 11:27:10 mysqld_safe mysqld from pid file /home/mysqlserver/62/localhost.pid ended

How to repeat:
restart mysql it would be repeat in master ,but slave work well.

it's occured yesterday in master ,we copy the slave as master ,run again, it's ok, but it occured again just.
[21 May 2013 6:40] gust zhang
my.cnf 

# Example MySQL config file for very large systems.
#
# This is for a large system with memory of 1G-2G where the system runs mainly
# MySQL.
#
# MySQL programs look for option files in a set of
# locations which depend on the deployment platform.
# You can copy this option file to one of those
# locations. For information about these locations, see:
# http://dev.mysql.com/doc/mysql/en/option-files.html
#
# In this file, you can use all long options that a program supports.
# If you want to know which options a program supports, run the program
# with the "--help" option.

# The following options will be passed to all MySQL clients
[client]
#password       = your_password
port            = 3308
socket          =/home/mysqlserver/62/mysql.sock

# Here follows entries for some specific programs

# The MySQL server
[mysqld]
port            = 3308
socket          =/home/mysqlserver/62/mysql.sock
skip-external-locking
key_buffer_size = 512M
max_allowed_packet = 16M
table_open_cache = 512
sort_buffer_size = 2M
read_buffer_size = 2M
read_rnd_buffer_size = 16M
myisam_sort_buffer_size = 64M
thread_cache_size = 8
query_cache_size = 256M
# Try number of CPU's*2 for thread_concurrency
thread_concurrency = 32
#innodb_force_recovery = 3
#innodb_purge_thread = 0 

       max_connections=50
       skip-name-resolve
       log_bin_trust_function_creators=1
       event_scheduler=1
       innodb_buffer_pool_size = 3024M
       expire_logs_days=5

       log-error=/home/mysqlserver/62/localhost.err
       datadir=/home/mysqlserver/62
       pid-file=/home/mysqlserver/62/localhost.pid

       binlog-do-db=game2010002
       binlog-do-db=game2010002_1
       binlog-do-db=game2010002_2
       binlog-do-db=game2010002_3
       binlog-do-db=game2010002_4
       binlog-do-db=game2010002_5
       binlog-do-db=game2010002_6
       binlog-do-db=game2010002_7
       binlog-do-db=game2010002_8
       binlog-do-db=game2010002log
       binlog-ignore-db=mysql
       binlog-ignore-db=test

# Don't listen on a TCP/IP port at all. This can be a security enhancement,
# if all processes that need to connect to mysqld run on the same host.
# All interaction with mysqld must be made via Unix sockets or named pipes.
# Note that using this option without enabling named pipes on Windows
# (via the "enable-named-pipe" option) will render mysqld useless!
# 
#skip-networking

# Replication Master Server (default)
# binary logging is required for replication
log-bin=mysql-bin

# required unique id between 1 and 2^32 - 1
# defaults to 1 if master-host is not set
# but will not function as a master if omitted
server-id       = 1

# Replication Slave (comment out master section to use this)
#
# To configure this host as a replication slave, you can choose between
# two methods :
#
# 1) Use the CHANGE MASTER TO command (fully described in our manual) -
#    the syntax is:
#
#    CHANGE MASTER TO MASTER_HOST=<host>, MASTER_PORT=<port>,
#    MASTER_USER=<user>, MASTER_PASSWORD=<password> ;
#
#    where you replace <host>, <user>, <password> by quoted strings and
#    <port> by the master's port number (3308 by default).
#
#    Example:
#
#    CHANGE MASTER TO MASTER_HOST='125.564.12.1', MASTER_PORT=3308,
#    MASTER_USER='joe', MASTER_PASSWORD='secret';
#
# OR
#
# 2) Set the variables below. However, in case you choose this method, then
#    start replication for the first time (even unsuccessfully, for example
#    if you mistyped the password in master-password and the slave fails to
#    connect), the slave will create a master.info file, and any later
#    change in this file to the variables' values below will be ignored and
#    overridden by the content of the master.info file, unless you shutdown
#    the slave server, delete master.info and restart the slaver server.
#    For that reason, you may want to leave the lines below untouched
#    (commented) and instead use CHANGE MASTER TO (see above)
#
# required unique id between 2 and 2^32 - 1
# (and different from the master)
# defaults to 2 if master-host is set
# but will not function as a slave if omitted
#server-id       = 2
#
# The replication master for this slave - required
#master-host     =   <hostname>
#
# The username the slave will use for authentication when connecting
# to the master - required
#master-user     =   <username>
#
# The password the slave will authenticate with when connecting to
# the master - required
#master-password =   <password>
#
# The port the master is listening on.
# optional - defaults to 3308
#master-port     =  <port>
#
# binary logging - not required for slaves, but recommended
#log-bin=mysql-bin
#
# binary logging format - mixed recommended 
#binlog_format=mixed

# Uncomment the following if you are using InnoDB tables
#innodb_data_home_dir =/home/mysqlserver/62server/mysql
#innodb_data_file_path = ibdata1:2000M;ibdata2:10M:autoextend
#innodb_log_group_home_dir =/home/mysqlserver/62server/mysql
# You can set .._buffer_pool_size up to 50 - 80 %
# of RAM but beware of setting memory usage too high
#innodb_buffer_pool_size = 384M
#innodb_additional_mem_pool_size = 20M
# Set .._log_file_size to 25 % of buffer pool size
#innodb_log_file_size = 256M
innodb_log_buffer_size = 64M
innodb_flush_log_at_trx_commit = 2
#innodb_lock_wait_timeout = 50

[mysqldump]
quick
max_allowed_packet = 16M

[mysql]
no-auto-rehash
# Remove the next comment character if you are not familiar with SQL
#safe-updates

[myisamchk]
key_buffer_size = 256M
sort_buffer_size = 256M
read_buffer = 2M
write_buffer = 2M

[mysqlhotcopy]
interactive-timeout
[27 May 2013 12:16] Sveta Smirnova
Thank you for the report.

Could you please send us full error log file, including records prior last crash after you tried to start the server.
[28 May 2013 2:29] gust zhang
i've commit the error whole log file ,please check it .

please notice log at "2013-05-21 10:50:08" .when start server something wrong maybe. i can commit the binlog if if you need it .
[29 May 2013 9:26] yang wang
Maybe you table include blob column
[29 May 2013 10:19] gust zhang
yes ,there are several blob field in table.
[10 Jun 2013 19:03] Sveta Smirnova
Thank you for the feedback.

I see your error log file is full of entries:

2013-05-25 10:21:50 7fafdda26700  InnoDB: Assertion failure in thread 140393314412288 in file btr0cur.cc line 283
InnoDB: Failing assertion: btr_page_get_next(get_block->frame, mtr) == page_get_page_no(page)

which started occurring since April, 20. These assertions look like table corruption.

Could you please check which tables affected and which queries cause the assertion.

You can try one of three and half following approaches.

1. Turn ON possibility to write core files. This can be done if you add option core to the my.cnf and adjust OS settings, so it allows user which runs mysqld to create core files of unlimited size.

2. Turn ON general query log, wait when crash occur again and send us general log together with error log. Or do research yourself: find time when server crashed and find list of transactions which were executed during that time.

2.5. In addition to 2. Turn ON InnoDB Monitor, so it will write current running transactions into error log file.

3. Run CHECK TABLE on every InnoDB table you have, so we can identify which is corrupted. Note, server will crash if it finds a problem.
[11 Jul 2013 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".