Bug #69825 InnoDB: Assertion failure in thread ... in file lock0wait.cc line 297
Submitted: 23 Jul 2013 12:46 Modified: 6 Aug 2013 14:37
Reporter: Przemyslaw Malkowski Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.6.12 OS:Any
Assigned to: CPU Architecture:Any
Tags: 5.6 GTID InnoDB relay-log-info-repository master-info-repository

[23 Jul 2013 12:46] Przemyslaw Malkowski
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.
[23 Jul 2013 12:48] Przemyslaw Malkowski
Error log with innodb force recovery=3

Attachment: innodb_recovery_3.err (application/octet-stream, text), 2.86 KiB.

[23 Jul 2013 12:50] Przemyslaw Malkowski
Core dump, compressed

Virus scan engine found a threat. This file might be infected. Attachment: core.22958.bz2 (application/x-bzip, text), 1.13 MiB.

[23 Jul 2013 12:50] Przemyslaw Malkowski
gdb output

Attachment: core.bt (application/octet-stream, text), 23.14 KiB.

[6 Aug 2013 6:25] Marko Mäkelä
According to the backtrace, the unexpected lock wait occurs on the InnoDB data dictionary table SYS_INDEXES at row_merge_drop_temp_indexes(). This is executed just after applying all redo log, and right before starting to allow user connections.

Luckily, you have a data set that can reproduce the problem. I believe that the problem should be repeatable with the system tablespace (ibdata* files) only. If you are using innodb_file_per_table=1 (keeping data in *.ibd files), the system tablespace file should be small, and should not contain too much of your data (except what happens to have been in the change buffer or the undo logs).

The core dump would only be useful when we also have the executables that produced it: the mysqld executable and any shared libraries that were linked to it.
[6 Aug 2013 14:37] Sinisa Milivojevic
This bug is a duplicate of the bug #69898. It should have been the opposite, since this bug is reported earlier then #69898, but as useful diagnostic info is uploaded to the bug #69898, so this bug becomes the duplicate.

You can follow the progress on the original bug.