Bug #77804 mysqld crash on broken InnoDB data during recovery
Submitted: 23 Jul 2015 0:44 Modified: 23 Jul 2015 13:52
Reporter: Martin Mokrejs Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S1 (Critical)
Version:5.6.24 OS:Linux
Assigned to: CPU Architecture:Any

[23 Jul 2015 0:44] Martin Mokrejs
Description:
Our server crashed due to power outage (UPS was drained) and mysql cannot recover InnoDB data and crashes during startup. I resolved the stacktrace below:

2015-07-23 02:17:17 5751 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-07-23 02:17:17 5751 [Note] InnoDB: The InnoDB memory heap is disabled
2015-07-23 02:17:17 5751 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-07-23 02:17:17 5751 [Note] InnoDB: Memory barrier is not used
2015-07-23 02:17:17 5751 [Note] InnoDB: Compressed tables use zlib 1.2.8
2015-07-23 02:17:17 5751 [Note] InnoDB: Using Linux native AIO
2015-07-23 02:17:17 5751 [Note] InnoDB: Not using CPU crc32 instructions
2015-07-23 02:17:17 5751 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2015-07-23 02:17:17 5751 [Note] InnoDB: Completed initialization of buffer pool
2015-07-23 02:17:17 5751 [Note] InnoDB: Highest supported file format is Barracuda.
2015-07-23 02:17:17 5751 [Note] InnoDB: The log sequence numbers 14091345 and 14091345 in ibdata files do not match the log sequence number 14137088 in the ib_logfiles!
2015-07-23 02:17:17 5751 [Note] InnoDB: Database was not shutdown normally!
2015-07-23 02:17:17 5751 [Note] InnoDB: Starting crash recovery.
2015-07-23 02:17:17 5751 [Note] InnoDB: Reading tablespace information from the .ibd files...
2015-07-23 02:17:17 5751 [Note] InnoDB: Restoring possible half-written data pages 
2015-07-23 02:17:17 5751 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Last MySQL binlog file position 0 19242, file name ./mysqld-bin.000050
00:17:17 UTC - 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=16777216
read_buffer_size=262144
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 = 134277 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
0x9be592 my_print_stacktrace + 56
0x6cfdb1 handle_fatal_signal + 1011
0x7f121b381d30 _end + 435100752
0xb35c09 _Z19dict_get_first_pathmPKc + 115
0xb3657c _Z39dict_check_tablespaces_and_store_max_id12dict_check_t + 1321
0xab4d62 _Z34innobase_start_or_create_for_mysqlv + 5493
0x9d9db8 _ZL13innobase_initPv + 2976
0x5fb3d8 _Z24ha_initialize_handlertonP13st_plugin_int + 131
0x772402 _ZL17plugin_initializeP13st_plugin_int + 110
0x772d9c _Z11plugin_initPiPPci + 1708
0x5ebcc3 _ZL22init_server_componentsv + 1932
0x5ec9c6 _Z11mysqld_mainiPPc + 1411
0x5e321d main + 32
0x7f121a9f6aa5 _end + 425093573
0x5e3139 _start + 41
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.

How to repeat:
These are crashed tables, cannot repeat.
[23 Jul 2015 1:34] Martin Mokrejs
Actually, here is from the mysqld.err a preceding entry. Not sure if I upgraded the tables or not, it is not logged in the error file obviously. Could this eventually cause the recovery to fail?

150311 16:29:55 [Warning] No argument was provided to --log-bin, and --log-bin-index was not used; so replication may break when this MySQL server acts as a master and has his hostname changed!! Please use '--log-bin=mysqld-bin
' to avoid this problem.
150311 16:29:55 InnoDB: The InnoDB memory heap is disabled
150311 16:29:55 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150311 16:29:55 InnoDB: Compressed tables use zlib 1.2.7
150311 16:29:55 InnoDB: Using Linux native AIO
150311 16:29:55 InnoDB: Initializing buffer pool, size = 128.0M
150311 16:29:55 InnoDB: Completed initialization of buffer pool
150311 16:29:56 InnoDB: highest supported file format is Barracuda.
150311 16:29:56  InnoDB: Warning: allocated tablespace 1, old maximum was 0
150311 16:29:56  InnoDB: Waiting for the background threads to start
150311 16:29:57 InnoDB: 5.5.30 started; log sequence number 14091345
150311 16:29:57 [Warning] /usr/sbin/mysqld: unknown option '--loose-federated'
150311 16:29:58 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
150311 16:29:58 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
150311 16:29:58 [Note] Server socket created on IP: '127.0.0.1'.
150311 16:29:58 [ERROR] Missing system table mysql.proxies_priv; please run mysql_upgrade to create it
150311 16:29:58 [ERROR] Native table 'performance_schema'.'events_waits_current' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'events_waits_history' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'events_waits_history_long' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'setup_consumers' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'setup_instruments' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'setup_timers' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'performance_timers' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'threads' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'events_waits_summary_by_thread_by_event_name' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'events_waits_summary_by_instance' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'events_waits_summary_global_by_event_name' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'file_summary_by_event_name' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'file_summary_by_instance' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'mutex_instances' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'rwlock_instances' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'cond_instances' has the wrong structure
150311 16:29:58 [ERROR] Native table 'performance_schema'.'file_instances' has the wrong structure
150311 16:29:58 [Note] Event Scheduler: Loaded 0 events
150311 16:29:58 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.30-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution
[23 Jul 2015 5:49] MySQL Verification Team
Hello Martin,

Thank you for the report.
This is most likely duplicate of Bug #72351

Thanks,
Umesh
[23 Jul 2015 13:52] Martin Mokrejs
Thank you, you were right, downgrading to 5.5.44 version enabled me to run through the recovery process:

150723 15:17:16 InnoDB: The InnoDB memory heap is disabled
150723 15:17:16 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150723 15:17:16 InnoDB: Compressed tables use zlib 1.2.8
150723 15:17:16 InnoDB: Using Linux native AIO
150723 15:17:16 InnoDB: Initializing buffer pool, size = 128.0M
150723 15:17:16 InnoDB: Completed initialization of buffer pool
150723 15:17:16 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
150723 15:17:16  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: Last MySQL binlog file position 0 19242, file name ./mysqld-bin.000050
150723 15:17:17 InnoDB: 5.5.44 started; log sequence number 14137088
150723 15:17:17 [Warning] /usr/sbin/mysqld: unknown option '--loose-federated'
150723 15:17:17 [Note] Recovering after a crash using mysqld-bin
150723 15:17:17 [Note] Starting crash recovery...
150723 15:17:17 [Note] Crash recovery finished.
150723 15:17:17 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
150723 15:17:17 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
150723 15:17:17 [Note] Server socket created on IP: '127.0.0.1'.
150723 15:17:17 [ERROR] Missing system table mysql.proxies_priv; please run mysql_upgrade to create it
150723 15:17:17 [ERROR] Native table 'performance_schema'.'events_waits_current' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'events_waits_history' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'events_waits_history_long' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'setup_consumers' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'setup_instruments' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'setup_timers' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'performance_timers' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'threads' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'events_waits_summary_by_thread_by_event_name' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'events_waits_summary_by_instance' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'events_waits_summary_global_by_event_name' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'file_summary_by_event_name' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'file_summary_by_instance' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'mutex_instances' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'rwlock_instances' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'cond_instances' has the wrong structure
150723 15:17:17 [ERROR] Native table 'performance_schema'.'file_instances' has the wrong structure
150723 15:17:17 [Note] Event Scheduler: Loaded 0 events
150723 15:17:17 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.44-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution

I did run mysql_update and things are fine again. Well, still need to go from 5.5.x to 5.6.x. ;-)