MySQL Bugs: #56245: InnoDB: Progress in percents: InnoDB: Error: trying to access page number 15392

Bug #56245	InnoDB: Progress in percents: InnoDB: Error: trying to access page number 15392
Submitted:	25 Aug 2010 10:46	Modified:	25 Aug 2010 15:10
Reporter:	Sébastien El Achkar	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: General	Severity:	S1 (Critical)
Version:	Ver 5.0.45 for redhat-linux-gnu on i686	OS:	Linux (CentOS)
Assigned to:		CPU Architecture:	Any
Tags:	IBData1, InnDB, Signal 11

Description:
I recently reboot my server and when he start, the deamon mysqld don't start, i have this message :

[root@localhost test]# service mysqld start
Timeout error occurred trying to start MySQL Daemon.
DÃ©marrage de MySQL : [Ã‰CHOUÃ‰]

This is what i see in the mysqld.log :

[root@localhost test]# /usr/libexec/mysqld -v
100825 13:38:11  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...
100825 13:38:11  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 8 1284009525.
100825 13:38:11  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: InnoDB: Error: trying to access page number 15392 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.
100825 13:38:11InnoDB: Assertion failure in thread 3086645504 in file fil0fil.c line 3959
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.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
100825 13:38:11 - 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=0
read_buffer_size=131072
max_used_connections=0
max_connections=100
threads_connected=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 217599 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=(nil)
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...
Cannot determine thread, fp=0xbff22b48, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x8187393
0x83f96bc
0x83d76a5
0x83d78eb
0x83e230d
0x83e3249
0x83e3777
0x83e3c27
0x8341abb
0x8250170
0x823f936
0x81863b6
0x8189bd5
0x7d1dec
0x80fa4e1
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.
[root@localhost test]# /usr/libexec/mysqld --version
/usr/libexec/mysqld  Ver 5.0.45 for redhat-linux-gnu on i686 (Source distribution)

result of resolve_stack_dump :

[root@localhost test]# resolve_stack_dump -s /tmp/mysqld.sym -n mysqld.stack | c++filt
0x8187393 handle_segfault + 755
0x83f96bc fil_io + 716
0x83d76a5 buf_LRU_invalidate_tablespace + 1333
0x83d78eb buf_read_recv_pages + 219
0x83e230d recv_apply_hashed_log_recs + 669
0x83e3249 recv_scan_log_recs + 2025
0x83e3777 recv_scan_log_recs + 3351
0x83e3c27 recv_recovery_from_checkpoint_start + 1175
0x8341abb innobase_start_or_create_for_mysql + 5851
0x8250170 innobase_init() + 880
0x823f936 ha_init() + 582
0x81863b6 unireg_abort + 582
0x8189bd5 main + 1109
0x7d1dec (?)
0x80fa4e1 _start + 33

How to repeat:
I shutdown my server unproperly and when i restart the deamon don't start.

Please, send your my.cnf file content and the results of:

ls -l

Linux command in the data directory.

my.cnf content :

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
old_passwords=1

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

 result ls -l :

[[root@localhost home]# ls -l /var/lib/mysql/
total 711428
drwx------ 2 mysql mysql     12288 dÃ©c  9  2009 cacti
drwx------ 2 mysql mysql      4096 dÃ©c  9  2009 eonweb
drwx------ 2 mysql mysql     12288 dÃ©c  9  2009 fruity
-rw-rw---- 1 mysql mysql  10485760 dÃ©c  9  2009 ibdata1
-rw-rw---- 1 mysql mysql 706740224 dÃ©c  9  2009 ibdata1.old
-rw-rw---- 1 mysql mysql   5242880 dÃ©c  9  2009 ib_logfile0
-rw-rw---- 1 mysql mysql   5242880 dÃ©c  9  2009 ib_logfile1
drwx------ 2 mysql mysql      4096 dÃ©c  9  2009 mysql
drwx------ 2 mysql mysql     12288 dÃ©c  9  2009 ndoutils
drwx------ 2 mysql mysql      4096 dÃ©c  9  2009 syslogng
drwx------ 2 mysql mysql      4096 sep  3  2009 test

That ibdata1 file you have is 10M in size (default value, as it is not set in my,cnf explictly) and is definitely too small to have page 15392 (with 16K pages InnoDB uses). There is another file:

-rw-rw---- 1 mysql mysql  10485760 dÃ©c  9  2009 ibdata1
-rw-rw---- 1 mysql mysql 706740224 dÃ©c  9  2009 ibdata1.old

ibdata1.old.

Are you sure you use correct my.cnf? Where that ibdata1.old file came from?

I find only one my.cnf file, so i think it's the correct file. And the ibdata1.old  was created automatically after the crash, i think...

[root@localhost ~]# find / -name my.cnf
/etc/my.cnf
[root@localhost ~]#

Then, please, try to rename ibdata1 to ibdata1.bak:

cp ibdata1 ibdata1.bak

and then substitute ibdata1 with ibdata1.old:

cp ibdata1.old ibdata1

and try to start server again. Inform about the results.

[root@localhost mysql]# /usr/libexec/mysqld 
100825 17:42:08  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...
100825 17:42:08  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 8 1284009525.
100825 17:42:08  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 
100825 17:42:08InnoDB: Assertion failure in thread 3054193552 in file log0recv.c line 773
InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page)==index->table->comp
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.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
100825 17:42:08 - 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=0
read_buffer_size=131072
max_used_connections=0
max_connections=100
threads_connected=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 217599 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=(nil)
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...
Cannot determine thread, fp=0xb60b3a88, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x8187393
0x83df5ca
0x83e10f8
0x83ce679
0x83f936b
0x833fa88
0x93545b
0x88ce5e
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/using-stack-trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do 
resolve it
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

[root@localhost test]# resolve_stack_dump -s /tmp/mysqld.sym -n mysqld.stack
0x8187393 handle_segfault + 755
0x83df5ca log_fsp_current_free_limit_set_and_checkpoint + 2618
0x83e10f8 recv_recover_page + 1048
0x83ce679 buf_page_io_complete + 1289
0x83f936b fil_aio_wait + 459
0x833fa88 srv_normalize_path_for_win + 72
0x93545b (?)
0x88ce5e (?)

Try to use forced recovery options as described in http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html. Or, if even with innodb_force_recovery=6 server will not start and allow to dump/select data, restore data from backup.

In any case, looks like your data on disk are corrupted to such extent that InnoDB can not use them. This is not a bug in MySQL code itself, IMHO, just badly corrupted data.

When i start mysqld with option innodb_force_recovery=6 it work! Thanks for your help.

So, I assume the problem was a result of data corruption, not a bug in the code.

https://bugs.mysql.com/bug.php?id=55543