InnoDB: Assertion failure in thread <n> in file log0recv.c line 1246 InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)

[Joshua H]

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona Ireland Ltd 2009-2012. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".

130328 01:33:00 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/etc/mysql/my.cnf" --defaults-group="mysqld" --prepare --target-dir=/srv/mysql/data --tmpdir=/tmp

xtrabackup_55 version 2.0.6 for Percona Server 5.5.16 Linux (x86_64) (revision id: undefined)
xtrabackup: cd to /srv/mysql/data
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=95141888, start_lsn=(312563257050)
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 95141888
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 95141888
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130328 1:33:02 InnoDB: The InnoDB memory heap is disabled
130328 1:33:02 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130328 1:33:02 InnoDB: Compressed tables use zlib 1.2.3
130328 1:33:02 InnoDB: Initializing buffer pool, size = 100.0M
130328 1:33:02 InnoDB: Completed initialization of buffer pool
130328 1:33:02 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 312563257050
130328 1:33:02 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 312568499712 (6 %)
InnoDB: Doing recovery: scanned up to log sequence number 312573742592 (12 %)
InnoDB: Doing recovery: scanned up to log sequence number 312578985472 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 312584228352 (24 %)
InnoDB: Doing recovery: scanned up to log sequence number 312589471232 (30 %)
130328 1:33:03 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 130328 1:36:17 InnoDB: Assertion failure in thread 140710830794496 in file log0recv.c line 1246
InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
Aborted (core dumped)
innobackupex: Error:
innobackupex: ibbackup failed at /usr//bin/innobackupex line 381.

[Alexey Kopytov (akopytov)]

This is most likely a server problem, or to be more specific, a problem with InnoDB not being crash-safe (and thus, backup-safe) under some circumstances.

We've been getting similar reports for XtraBackup, but there are also similar reports against the server, e.g.:

http://www.chriscalender.com/?p=355
http://bugs.mysql.com/bug.php?id=64429

In both cases the assertion is triggered after recovering from a crash (a hardware crash in the first case, or due to another assertion failure in the second one).

I have changed the project to XtraBackup though, since the problem occurred there.

It is rather tricky to debug and fix this in either XtraBackup or server, because as I wrote, the most likely reason is crash or backup occurring at some sensitive time.

I assume you don't have a reproducible case. But some details on what the server was doing at the time when the backup was taken may be helpful to investigate it further.

[George Ormond Lorch III (gl-az)]

Reproduced against XB 2.0 (revno 555) and PS 5.5 (revno 506)

This occurred in xtrabackup while preparing a series of incremental backups that were made while running RQG in a loop:

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona Ireland Ltd 2009-2012. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".

130507 08:36:13 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/mnt/var/cpb/test-4/mysql.1/my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/var/cpb/test-4/restore-working --apply-log-only --incremental-dir=/mnt/var/cpb/test-4/backup-0.3 --tmpdir=/mnt/var/cpb/test-4/mysql.1/tmp

xtrabackup_55 version 2.0.6 for Percona Server 5.5.16 Linux (x86_64) (revision id: undefined)
incremental backup from 966406583 is enabled.
xtrabackup: cd to /mnt/var/cpb/test-4/restore-working
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=770506752, start_lsn=(1169936984)
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /mnt/var/cpb/test-4/backup-0.3
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 770506752
130507 8:36:14 InnoDB: Warning: allocated tablespace 1104, old maximum was 9
xtrabackup: page size for /mnt/var/cpb/test-4/backup-0.3/ibdata1.delta is 16384 bytes
Applying /mnt/var/cpb/test-4/backup-0.3/ibdata1.delta to ././ibdata1...
xtrabackup: page size for /mnt/var/cpb/test-4/backup-0.3/rqg1/table100_innodb_default_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_default_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#1121.ibd
Applying /mnt/var/cpb/test-4/backup-0.3/rqg1/table100_innodb_default_int_autoinc.ibd.delta to ././rqg1/table100_innodb_default_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-4/backup-0.3/rqg1/table100_innodb_dynamic.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_dynamic.ibd to ./rqg1/xtrabackup_tmp_#1032.ibd
Applying /mnt/var/cpb/test-4/backup-0.3/rqg1/table100_innodb_dynamic.ibd.delta to ././rqg1/table100_innodb_dynamic.ibd...
xtrabackup: page size for /mnt/var/cpb/test-4/backup-0.3/rqg1/table500_innodb_dynamic_int.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_dynamic_int.ibd to ./rqg1/xtrabackup_tmp_#1077.ibd
Applying /mnt/var/cpb/test-4/backup-0.3/rqg1/table500_innodb_dynamic_int.ibd.delta to ././rqg1/table500_innodb_dynamic_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-4/backup-0.3/rqg1/table500_innodb_default_int.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_default_int.ibd to ./rqg1/xtrabackup_tmp_#1119.ibd
Applying /mnt/var/cpb/test-4/backup-0.3/rqg1/table500_innodb_default_int.ibd.delta to ././rqg1/table500_innodb_default_int.ibd...
xtrabackup: page size for /...

[George Ormond Lorch III (gl-az)]

my.cnf
[client]
port=10000
socket=/mnt/var/cpb/test-4/mysql.1/mysql.sock
[mysqld]
basedir=/mnt/bin/ps-5.5
datadir=/mnt/var/cpb/test-4/mysql.1/data
tmpdir=/mnt/var/cpb/test-4/mysql.1/tmp
port=10000
socket=/mnt/var/cpb/test-4/mysql.1/mysql.sock
pid-file=/mnt/var/cpb/test-4/mysql.1/mysql.pid
console
user=root
server-id=1
innodb_buffer_pool_size=1G
innodb_file_format=antelope
innodb_file_per_table=1
innodb_log_file_size=512M

[George Ormond Lorch III (gl-az)]

Thread 11 (Thread 0x7f7a121fc700 (LWP 6282)):
#0 0x0000003b9160b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004a8da9 in os_cond_wait (event=0x2b7c540, reset_sig_count=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x2b7c540, reset_sig_count=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0sync.c:609
#3 0x00000000004a6089 in os_aio_simulated_handle (global_segment=1, message1=0x7f7a121fbe68, message2=0x7f7a121fbe60, type=0x7f7a121fbe58, space_id=0x7f7a121fbe50) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0file.c:5097
#4 0x000000000046e794 in fil_aio_wait (segment=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5701
#5 0x00000000004ea248 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/srv/srv0start.c:485
#6 0x0000003b91607851 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003b90ee890d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7f7a135fe700 (LWP 6281)):
#0 0x0000003b9160b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004a8da9 in os_cond_wait (event=0x2b7c4c0, reset_sig_count=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x2b7c4c0, reset_sig_count=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0sync.c:609
#3 0x00000000004a6089 in os_aio_simulated_handle (global_segment=0, message1=0x7f7a135fde68, message2=0x7f7a135fde60, type=0x7f7a135fde58, space_id=0x7f7a135fde50) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0file.c:5097
#4 0x000000000046e794 in fil_aio_wait (segment=0) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5701
#5 0x00000000004ea248 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/srv/srv0start.c:485
#6 0x0000003b91607851 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003b90ee890d in clone () from /lib64/libc.so.6

Thread 9 (Thread 0x7f7a12bfd700 (LWP 6290)):
#0 0x0000003b9160b43c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004a8da9 in os_cond_wait (event=0x2b7c940, reset_sig_count=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x2b7c940, reset_sig_count=1) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0sync.c:609
#3 0x00000000004a6089 in os_aio_simulated_handle (global_segment=9, message1=0x7f7a12bfce68, message2=0x7f7a12bfce60, type=0x7f7a12bfce58, space_id=0x7f7a12bfce50) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/os/os0file.c:5097
#4 0x000000000046e794 in fil_aio_wait (segment=9) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5701
#5 0x00000000004ea248 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.0/Percona-Server-5.5/storage/innobase/srv/srv0start.c:485
#6 0x0000003b91607851 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003b90ee890d in clone () from /lib64/libc.so.6

Thread 8 (Thread 0x7f7a13fff700 (LWP 6289)):
#0 0x0000003b9160b43c in pthread_cond_wait@@GLIBC_2.3.2 () fro...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-1208