Description:
This has happened after unplanned power outage of 5.6.12 slave instance. Unable to start the service after the incident.
Crash safe replication is enabled (slave_master_info, slave_relay_log_info, slave_worker_info tables present in mysql db).
Here is the error log:
130723 12:23:05 mysqld_safe Starting mysqld daemon with databases from /home/sandbox/oracle5.6.12/data
2013-07-23 12:23:05 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-07-23 12:23:05 22958 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)
2013-07-23 12:23:05 22958 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)
2013-07-23 12:23:05 22958 [Note] Plugin 'FEDERATED' is disabled.
2013-07-23 12:23:05 22958 [Note] InnoDB: The InnoDB memory heap is disabled
2013-07-23 12:23:05 22958 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-07-23 12:23:05 22958 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-07-23 12:23:05 22958 [Note] InnoDB: Using Linux native AIO
2013-07-23 12:23:05 22958 [Note] InnoDB: Using CPU crc32 instructions
2013-07-23 12:23:05 22958 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2013-07-23 12:23:05 22958 [Note] InnoDB: Completed initialization of buffer pool
2013-07-23 12:23:05 22958 [Note] InnoDB: Highest supported file format is Barracuda.
2013-07-23 12:23:05 22958 [Note] InnoDB: Log scan progressed past the checkpoint lsn 343298871
2013-07-23 12:23:05 22958 [Note] InnoDB: Database was not shutdown normally!
2013-07-23 12:23:05 22958 [Note] InnoDB: Starting crash recovery.
2013-07-23 12:23:05 22958 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-07-23 12:23:05 22958 [Note] InnoDB: Restoring possible half-written data pages
2013-07-23 12:23:05 22958 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 343298951
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 1312000
InnoDB: Last MySQL binlog file position 0 5298, file name bc1hywcd11-bin.000002
2013-07-23 12:23:06 7f4644fd4740 InnoDB: Error: a record lock wait happens in a dictionary operation!
InnoDB: index "CLUST_IND" of table "SYS_INDEXES".
InnoDB: Submit a detailed bug report to http://bugs.mysql.com
2013-07-23 12:23:06 7f4644fd4740 InnoDB: Assertion failure in thread 139939781887808 in file lock0wait.cc line 297
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.
10:23:06 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=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=151
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 = 68221 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
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld(my_print_stacktrace+0x35)[0x8f8e95]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld(handle_fatal_signal+0x3e8)[0x66cba8]
/lib64/libpthread.so.0[0x31b960f000]
/lib64/libc.so.6(gsignal+0x35)[0x31b9235c55]
/lib64/libc.so.6(abort+0x148)[0x31b9237408]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x9bba47]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x9ecdcf]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x9ed290]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0xa044f6]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x9c1815]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0xa3b124]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x983da0]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x46)[0x58ad86]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x6f4870]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld(_Z11plugin_initPiPPci+0x80d)[0x6f7c8d]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld[0x5801ba]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld(_Z11mysqld_mainiPPc+0x31b)[0x5835fb]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x31b9221a05]
/home/sandbox/tarballs/oracle5.6.12/bin/mysqld(__gxx_personality_v0+0x2d9)[0x5770a9]
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.
Writing a core file
130723 12:23:06 mysqld_safe mysqld from pid file /home/sandbox/oracle5.6.12/data/mysql_sandbox15612.pid ended
At the binlog position mentioned in the error log we can see:
# at 5298
#130625 12:57:33 server id 1 end_log_pos 5346 CRC32 0x26279563 GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '3a1364e6-dcf1-11e2-9e41-00155da0de16:525522'/*!*/;
InnoDB starts from innodb_force_recovery set at 3.
Core dump and gdb (gdb --batch --quiet -ex "set logging on" -ex "set pagination 0" -ex "thread apply all bt full" -ex "quit") output attached.
How to repeat:
Unable to reproduce test case, but I have the datadir archived and able to reproduce the crash on every start attempt.
