0

I ran into an InnoDB issue that only seemed to get worse as I tried to fix it. Started with InnoDB: Unable to lock ./ibdata1, error: 11, I moved and then copied it back. I soon had an ib_logfile issue as well, resolution failed, and at this point I realized that there was indeed still a mysql process running that I missed, so I killed it with killall -9 mysqld. Previous resolution attempts to this point have now brought me to the point of an Assertion failure. At this point I'm just trying not to trip over my own feet.

I've started the DB in recovery mode (level "3") and dumped my DB's. About 7gb total. The error, when not in recovery mode, is this:

141206 16:02:32 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql/
141206 16:02:32  InnoDB: Initializing buffer pool, size = 6.0G
141206 16:02:33  InnoDB: Completed initialization of buffer pool
InnoDB: Log scan progressed past the checkpoint lsn 546 4190820000
141206 16:02:33  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 546 4190831828
InnoDB: Transaction 0 360762750 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 0 360763136
141206 16:02:33  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 6595, file name /var/lib/mysql/mysql-bin.000817
InnoDB: Starting in background the rollback of uncommitted transactions
141206 16:02:34  InnoDB: Rollback of non-prepared transactions completed
141206 16:02:34  InnoDB: Started; log sequence number 546 4190831828
/usr/libexec/mysqld: File '/var/log/mysql-slow.log' not found (Errcode: 13)
141206 16:02:34 [ERROR] Could not use /var/log/mysql-slow.log for logging (error 13). Turning logging off for the whole duration of the MySQL server process. To turn it on again: fix the cause, shutdown the MySQL server and restart it.
141206 16:02:34  InnoDB: Starting recovery for XA transactions...
141206 16:02:34  InnoDB: Transaction 0 360762750 in prepared state after recovery
141206 16:02:34  InnoDB: Transaction contains changes to 1 rows
141206 16:02:34  InnoDB: 1 transactions in prepared state after recovery
141206 16:02:34 [Note] Found 1 prepared transaction(s) in InnoDB
InnoDB: Error: trying to access page number 997017014 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
141206 16:02:34  InnoDB: Assertion failure in thread 140371479300064 in file fil/fil0fil.c line 4135
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.1/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
16:02:34 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=33554432
read_buffer_size=131072
max_used_connections=0
max_threads=500
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 = 1125975 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/libexec/mysqld(my_print_stacktrace+0x29) [0x850989]
/usr/libexec/mysqld(handle_fatal_signal+0x483) [0x6a3ef3]
/lib64/libpthread.so.0(+0xf710) [0x7faac7e76710]
/lib64/libc.so.6(gsignal+0x35) [0x7faac64ac635]
/lib64/libc.so.6(abort+0x175) [0x7faac64ade15]
/usr/libexec/mysqld(fil_io+0x36e) [0x767e2e]
/usr/libexec/mysqld() [0x74fa03]
/usr/libexec/mysqld(buf_read_page+0x225) [0x750445]
/usr/libexec/mysqld(buf_page_get_gen+0x393) [0x749923]
/usr/libexec/mysqld(flst_insert_before+0x256) [0x772056]
/usr/libexec/mysqld(trx_purge_add_update_undo_to_history+0xf7) [0x7ccbe7]
/usr/libexec/mysqld(trx_undo_update_cleanup+0x29) [0x7dc789]
/usr/libexec/mysqld(trx_commit_off_kernel+0x1d9) [0x7db179]
/usr/libexec/mysqld(trx_finish_rollback_off_kernel+0x48) [0x7d3b58]
/usr/libexec/mysqld() [0x7a1f7a]
/usr/libexec/mysqld(que_run_threads+0x1f4) [0x7a21d4]
/usr/libexec/mysqld(trx_general_rollback_for_mysql+0xc0) [0x7d5390]
/usr/libexec/mysqld(trx_rollback_for_mysql+0x95) [0x7d5795]
/usr/libexec/mysqld() [0x732840]
/usr/libexec/mysqld() [0x73288b]
/usr/libexec/mysqld() [0x69976e]
/usr/libexec/mysqld(plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int*, void*), int, unsigned int, void*)+0x140) [0x7161e0]
/usr/libexec/mysqld(ha_recover(st_hash*)+0x9f) [0x6977ef]
/usr/libexec/mysqld() [0x5bf409]
/usr/libexec/mysqld(main+0x1b3) [0x5c1af3]
/lib64/libc.so.6(__libc_start_main+0xfd) [0x7faac6498d5d]
/usr/libexec/mysqld() [0x5098f9]
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.
141206 16:02:34 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended

At this point, will dropping and restoring the DB's be the next step, or is there something more or less invasive that should be done?

  • 1
    Not just to be glib, but at this point, and probably even a couple points ago,I would have just restored form backups and been done with it. You do have backups to restore from, don't you? – HopelessN00b Dec 6 '14 at 17:05
2

In general case innodb_force_recovery mode is supposed to let a user to start InnoDB and dump valuable data.

A common belief InnoDB will heal tablespace after enabling innodb_force_recovery. No, it won't. (In some cases you can fix a tablespace dropping particular tables, but that's another story).

If you are lucky enough and MySQL starts the next step is to take dump from the database

mysqldump --skip-lock-tables -A > my_database.sql

Then you need to wipe out all InnoDB files, and restore the database from the dump

mysql < my_database.sql
  • Yup! This is exactly what I did shortly after posting this. I moved all ibdata and ib_logfile files and InnoDB table files/directories and restarted MYSQL. Worked like a champ. – Tim Dec 6 '14 at 20:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.