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

Reported by George Ormond Lorch III on 2013-05-07
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona XtraBackup
High
Alexey Kopytov
2.0
High
Alexey Kopytov
2.1
High
Alexey Kopytov

Bug Description

May be duplicate of:
https://bugs.launchpad.net/percona-xtrabackup/+bug/380431 or
https://bugs.launchpad.net/percona-xtrabackup/+bug/1161280

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 04:57:16 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/mnt/var/cpb/test-9/mysql.1/my.cnf" --defaults-group="mysqld" --prepare --target-dir=/mnt/var/cpb/test-9/restore-working --apply-log-only --incremental-dir=/mnt/var/c
pb/test-9/backup-0.2 --tmpdir=/mnt/var/cpb/test-9/mysql.1/tmp

xtrabackup_55 version 2.1.0beta1 for Percona Server 5.5.16 Linux (x86_64) (revision id: undefined)
incremental backup from 889443043 is enabled.
xtrabackup: cd to /mnt/var/cpb/test-9/restore-working
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=141885440, start_lsn=(889443043)
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-9/backup-0.2
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 141885440
130507 4:57:17 InnoDB: Warning: allocated tablespace 108, old maximum was 9
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/ibdata1.delta is 16384 bytes
Applying /mnt/var/cpb/test-9/backup-0.2/ibdata1.delta to ././ibdata1...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_default_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_default_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#94.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_default_int_autoinc.ibd.delta to ././rqg1/table100_innodb_default_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_dynamic.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_dynamic.ibd to ./rqg1/xtrabackup_tmp_#90.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_dynamic.ibd.delta to ././rqg1/table100_innodb_dynamic.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/s.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/s.ibd.delta to ././rqg1/s.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_dynamic_int.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_dynamic_int.ibd to ./rqg1/xtrabackup_tmp_#102.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_dynamic_int.ibd.delta to ././rqg1/table500_innodb_dynamic_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_default_int.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_default_int.ibd to ./rqg1/xtrabackup_tmp_#70.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_default_int.ibd.delta to ././rqg1/table500_innodb_default_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_default.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_default.ibd to ./rqg1/xtrabackup_tmp_#111.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_default.ibd.delta to ././rqg1/table100_innodb_default.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_compressed.ibd.delta is 8192 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_compressed.ibd to ./rqg1/xtrabackup_tmp_#108.ibd
zip_size = 8192
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_compressed.ibd.delta to ././rqg1/table100_innodb_compressed.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_dynamic_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_dynamic_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#96.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_dynamic_int_autoinc.ibd.delta to ././rqg1/table500_innodb_dynamic_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_default_int.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_default_int.ibd to ./rqg1/xtrabackup_tmp_#100.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_default_int.ibd.delta to ././rqg1/table100_innodb_default_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/j.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/j.ibd.delta to ././rqg1/j.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_compressed_int_autoinc.ibd.delta is 8192 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_compressed_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#50.ibd
zip_size = 8192
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_compressed_int_autoinc.ibd.delta to ././rqg1/table500_innodb_compressed_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_dynamic_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_dynamic_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#93.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_dynamic_int_autoinc.ibd.delta to ././rqg1/table100_innodb_dynamic_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_compressed_int_autoinc.ibd.delta is 8192 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_compressed_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#114.ibd
zip_size = 8192
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_compressed_int_autoinc.ibd.delta to ././rqg1/table100_innodb_compressed_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_compressed_int.ibd.delta is 8192 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_compressed_int.ibd to ./rqg1/xtrabackup_tmp_#85.ibd
zip_size = 8192
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_compressed_int.ibd.delta to ././rqg1/table500_innodb_compressed_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_default_int_autoinc.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_default_int_autoinc.ibd to ./rqg1/xtrabackup_tmp_#105.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_default_int_autoinc.ibd.delta to ././rqg1/table500_innodb_default_int_autoinc.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_compressed.ibd.delta is 8192 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_compressed.ibd to ./rqg1/xtrabackup_tmp_#75.ibd
zip_size = 8192
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_compressed.ibd.delta to ././rqg1/table500_innodb_compressed.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_compressed_int.ibd.delta is 8192 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_compressed_int.ibd to ./rqg1/xtrabackup_tmp_#91.ibd
zip_size = 8192
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_compressed_int.ibd.delta to ././rqg1/table100_innodb_compressed_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/d.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/d.ibd.delta to ././rqg1/d.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_dynamic.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_dynamic.ibd to ./rqg1/xtrabackup_tmp_#110.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_dynamic.ibd.delta to ././rqg1/table500_innodb_dynamic.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/u.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/u.ibd.delta to ././rqg1/u.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_default.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table500_innodb_default.ibd to ./rqg1/xtrabackup_tmp_#113.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table500_innodb_default.ibd.delta to ././rqg1/table500_innodb_default.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_dynamic_int.ibd.delta is 16384 bytes
xtrabackup: Renaming ./rqg1/table100_innodb_dynamic_int.ibd to ./rqg1/xtrabackup_tmp_#106.ibd
Applying /mnt/var/cpb/test-9/backup-0.2/rqg1/table100_innodb_dynamic_int.ibd.delta to ././rqg1/table100_innodb_dynamic_int.ibd...
xtrabackup: page size for /mnt/var/cpb/test-9/backup-0.2/PERCONA_SCHEMA/backup_test_mark.ibd.delta is 16384 bytes
Applying /mnt/var/cpb/test-9/backup-0.2/PERCONA_SCHEMA/backup_test_mark.ibd.delta to ././PERCONA_SCHEMA/backup_test_mark.ibd...
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-9/backup-0.2
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 141885440
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
130507 4:57:17 InnoDB: The InnoDB memory heap is disabled
130507 4:57:17 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130507 4:57:17 InnoDB: Compressed tables use zlib 1.2.3
130507 4:57:17 InnoDB: Initializing buffer pool, size = 100.0M
130507 4:57:17 InnoDB: Completed initialization of buffer pool
130507 4:57:17 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 889443043
130507 4:57:17 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 894685696 (4 %)
InnoDB: Doing recovery: scanned up to log sequence number 899928576 (8 %)
InnoDB: Doing recovery: scanned up to log sequence number 905171456 (12 %)
InnoDB: Doing recovery: scanned up to log sequence number 910414336 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 915657216 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 920900096 (24 %)
InnoDB: Doing recovery: scanned up to log sequence number 926142976 (29 %)
InnoDB: Doing recovery: scanned up to log sequence number 931385856 (33 %)
InnoDB: Doing recovery: scanned up to log sequence number 936628736 (37 %)
InnoDB: Doing recovery: scanned up to log sequence number 941871616 (41 %)
InnoDB: Doing recovery: scanned up to log sequence number 947114496 (45 %)
InnoDB: Doing recovery: scanned up to log sequence number 952357376 (49 %)
130507 4:57:17 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 32 33 34 (cannot find space: 117) (cannot find space: 164) (cannot find space: 176) (cannot find space: 105)35 (cannot find space: 66) (cannot find space: 69) (cannot find space: 35)36 (cannot find space: 167) (cannot find space: 168)37 (cannot find space: 134)38 39 (cannot find space: 50) (cannot find space: 44)40 41 (cannot find space: 138) (cannot find space: 141) (cannot find space: 144) (cannot find space: 148) (cannot find space: 161)42 (cannot find space: 31)43 (cannot find space: 163)44 (cannot find space: 169)45 (cannot find space: 128)46 47 (cannot find space: 156)48 (cannot find space: 136)49 (cannot find space: 44) (cannot find space: 104) (cannot find space: 61) (cannot find space: 89) (cannot find space: 105) (cannot find space: 109) (cannot find space: 121) (cannot find space: 125) (cannot find space: 78) (cannot find space: 110) (cannot find space: 43) (cannot find space: 91) (cannot find space: 34) (cannot find space: 35) (cannot find space: 37) (cannot find space: 49) (cannot find space: 50) (cannot find space: 51) (cannot find space: 66) (cannot find space: 69) (cannot find space: 99) (cannot find space: 100) (cannot find space: 101) (cannot find space: 103) (cannot find space: 112) (cannot find space: 117) (cannot find space: 118) (cannot find space: 57)50 (cannot find space: 36)51 (cannot find space: 42) (cannot find space: 58) (cannot find space: 45) (cannot find space: 92) (cannot find space: 62) (cannot find space: 31) (cannot find space: 32)52 (cannot find space: 72)53 (cannot find space: 82)54 (cannot find space: 29)55 56 57 (cannot find space: 56) (cannot find space: 59)58 (cannot find space: 164)59 60 61 62 (cannot find space: 101)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: Doing recovery: scanned up to log sequence number 957600256 (54 %)
InnoDB: Doing recovery: scanned up to log sequence number 962843136 (58 %)
InnoDB: Doing recovery: scanned up to log sequence number 968086016 (62 %)
InnoDB: Doing recovery: scanned up to log sequence number 973328896 (66 %)
InnoDB: Doing recovery: scanned up to log sequence number 978571776 (70 %)
InnoDB: Doing recovery: scanned up to log sequence number 983814656 (74 %)
InnoDB: Doing recovery: scanned up to log sequence number 989057536 (78 %)
InnoDB: Doing recovery: scanned up to log sequence number 994300416 (83 %)
130507 4:57:19 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 (cannot find space: 369) (cannot find space: 343) (cannot find space: 374) (cannot find space: 346) (cannot find space: 347)130507 4:57:19 InnoDB: Assertion failure in thread 140419081942784 in file log0recv.c line 1105
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.
innobackupex: Error:
innobackupex: ibbackup failed at /mnt/bin/xb-2.1/innobackupex line 386.

George Ormond Lorch III (gl-az) wrote :

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

George Ormond Lorch III (gl-az) wrote :
Download full text (13.9 KiB)

Backtrace:
Thread 11 (Thread 0x7fb5e4e29700 (LWP 29110)):
#0 0x0000003b90e7939c in _int_malloc () from /lib64/libc.so.6
#1 0x0000003b90e7a911 in malloc () from /lib64/libc.so.6
#2 0x00000000004a422c in mem_heap_create_block (heap=0x0, n=<value optimized out>, type=0, file_name=0x576af8 "/mnt/xb-2.1/Percona-Server-5.5/storage/innobase/dict/dict0mem.c", line=73) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/mem/mem0mem.c:333
#3 0x00000000004667c0 in mem_heap_create_func (name=0x57f8e1 "LOG_DUMMY", space=0, n_cols=1, flags=0) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/include/mem0mem.ic:443
#4 dict_mem_table_create (name=0x57f8e1 "LOG_DUMMY", space=0, n_cols=1, flags=0) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/dict/dict0mem.c:73
#5 0x00000000004a5b3e in mlog_parse_index (ptr=0x7fb5d76e3340 "/逡", end_ptr=<value optimized out>, comp=<value optimized out>, index=0x7fb5e4e287d8) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/mtr/mtr0log.c:565
#6 0x000000000049d87e in recv_parse_or_apply_log_rec_body (type=9 '\t', ptr=<value optimized out>, end_ptr=0x7fb5d76e3397 "", block=0x7fb5d69904c8, mtr=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/log/log0recv.c:1099
#7 0x00000000004a21eb in recv_recover_page_func (just_read_in=<value optimized out>, block=0x7fb5d69904c8) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/log/log0recv.c:1674
#8 0x0000000000442191 in buf_page_io_complete (bpage=0x7fb5d69904c8) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/buf/buf0buf.c:4074
#9 0x000000000047439a in fil_aio_wait (segment=5) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5744
#10 0x00000000004f3628 in io_handler_thread (arg=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/srv/srv0start.c:486
#11 0x0000003b91607851 in start_thread () from /lib64/libpthread.so.0
#12 0x0000003b90ee890d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7fb5e622d720 (LWP 29093)):
#0 0x0000003b9160ec0d in fsync () from /lib64/libpthread.so.0
#1 0x00000000004a9abb in os_file_fsync (file=10, metadata=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0file.c:2081
#2 0x00000000004aa4c9 in os_file_flush_func (file=<value optimized out>, metadata=<value optimized out>) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0file.c:2184
#3 0x000000000046b285 in pfs_os_file_flush_func (space_id=<value optimized out>, metadata=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/include/os0file.ic:385
#4 fil_flush (space_id=<value optimized out>, metadata=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5832
#5 0x0000000000473752 in fil_extend_space_to_desired_size (actual_size=0x7fffcdfcb668, space_id=378, size_after_extend=10) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5032
#6 0x0000000000474b4b in _fil_io (type=10, sync=<value optimized out>, space_id=378, zip_size=0, block_offset=9, byte_offset=0, len=16384, buf=0x7fb5dc1f8000, message=0x7fb5d69a2000, trx=0x0)
    at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5442
#7 0x000000000044ef34 in buf_read_page_low (err=0x7fffcdfcb768, ...

tags: added: i31441
summary: - InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) ==
- dict_table_is_comp(index->table)
+ InnoDB: Assertion failure in thread 140419081942784 in file log0recv.c
+ line 1105InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page)
+ == dict_table_is_comp(index->table)
summary: InnoDB: Assertion failure in thread 140419081942784 in file log0recv.c
- line 1105InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page)
- == dict_table_is_comp(index->table)
+ line 1105 InnoDB: Failing assertion: !page ||
+ (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)
summary: - InnoDB: Assertion failure in thread 140419081942784 in file log0recv.c
- line 1105 InnoDB: Failing assertion: !page ||
- (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)
+ InnoDB: Assertion failure in thread <nr> in file log0recv.c line 1105
+ InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) ==
+ dict_table_is_comp(index->table)
tags: added: i31562
George Ormond Lorch III (gl-az) wrote :

Debugging a bit and thought I'd share a little more info:

record type = MLOG_COMP_REC_DELETE
dict_table_is_comp(index->table) is true
the page is not compact as seen by the page header:
(gdb) x/32whx (page + 38)
0x7ff4ec220026: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000
0x7ff4ec220036: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000
0x7ff4ec220046: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000
0x7ff4ec220056: 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000 0x0000

Thus the assertion.

Here is the complete log record as passed into recv_parse_or_apply_log_rec_body, 192 bytes:
(gdb) x/192bx (buf)
0x7ff4f17c3878: 0x00 0x5d 0x00 0x01 0x80 0x04 0x80 0x06
0x7ff4f17c3880: 0x80 0x07 0x00 0x03 0x00 0x03 0x00 0x04
0x7ff4f17c3888: 0x00 0x04 0x00 0x00 0x80 0x01 0x7f 0xff
0x7ff4f17c3890: 0x80 0x00 0x00 0x00 0x80 0x03 0x00 0x00
0x7ff4f17c3898: 0x7f 0xff 0x80 0x04 0x00 0x03 0x00 0x01
0x7ff4f17c38a0: 0x7f 0xff 0x00 0x04 0x7f 0xff 0x00 0x00
0x7ff4f17c38a8: 0x00 0x00 0x80 0x03 0xff 0xff 0x80 0x00
0x7ff4f17c38b0: 0x00 0x03 0x00 0x03 0x7f 0xff 0x80 0x00
0x7ff4f17c38b8: 0x00 0x01 0xff 0xff 0xff 0xff 0xff 0xff
0x7ff4f17c38c0: 0x80 0x00 0x80 0x04 0x80 0x01 0x7f 0xff
0x7ff4f17c38c8: 0x7f 0xff 0x80 0x00 0x00 0x04 0xff 0xff
0x7ff4f17c38d0: 0xff 0xff 0x00 0x03 0x80 0x01 0x00 0x04
0x7ff4f17c38d8: 0x80 0x00 0x00 0x00 0x80 0x00 0x80 0x04
0x7ff4f17c38e0: 0x7f 0xff 0x00 0x00 0x7f 0xff 0x7f 0xff
0x7ff4f17c38e8: 0x00 0x04 0x80 0x04 0x00 0x04 0x7f 0xff
0x7ff4f17c38f0: 0x7f 0xff 0x00 0x01 0x00 0x04 0x00 0x00
0x7ff4f17c38f8: 0x00 0x00 0x80 0x00 0x00 0x00 0xff 0xff
0x7ff4f17c3900: 0x7f 0xff 0x7f 0xff 0x00 0x00 0x80 0x04
0x7ff4f17c3908: 0x00 0x04 0x00 0x01 0x80 0x03 0x00 0x00
0x7ff4f17c3910: 0xff 0xff 0x00 0x00 0x00 0x00 0x00 0x00
0x7ff4f17c3918: 0xff 0xff 0x7f 0xff 0x80 0x00 0x7f 0xff
0x7ff4f17c3920: 0x00 0x04 0x00 0x00 0x00 0x04 0x80 0x04
0x7ff4f17c3928: 0x00 0x00 0x00 0x00 0x7f 0xff 0x7f 0xff
0x7ff4f17c3930: 0x00 0x01 0x00 0x04 0x00 0x01 0x0a 0xf4

George Ormond Lorch III (gl-az) wrote :

Something doesn't look right in recv_recover_page_func. The recv_addr->rec_list looks a bit hosed. Really 18410435450981319680 log records for a single page for a small, short, simple test?

(gdb) p recv_addr->rec_list
$18 = {count = 18410435450981319680, start = 0x38000000080, end = 0x10003000480ff7f}
(gdb) p *(recv_addr->rec_list.start)
Cannot access memory at address 0x38000000080

<thinking_aloud>Could it be that we have some memory corruption and are trying to process a bogus log record?</thinking_aloud>

George Ormond Lorch III (gl-az) wrote :

And to continue on that thought train of hosed memory, state looks off as well as the remainder of the addresses:

(gdb) p *recv_addr
$19 = {state = 16801024, space = 109053056, page_no = 50333568, rec_list = {count = 18410435450981319680, start = 0x38000000080, end = 0x10003000480ff7f}, addr_hash = 0xff7f0400ff7f}

George Ormond Lorch III (gl-az) wrote :
Download full text (3.6 KiB)

OK, the memory corruption seems that it was gdb/optimizations. After building XB and mini-InnoDB with optimizations off, the recv_addr and others look much more rational. Now...

Something is out of sync between the bpage read in the buf_page_io_complete and the actual page...

From buf_page_io_complete:
(gdb)p *bpage
$5 = {space = 24, offset = 3, state = 5, flush_type = 0, io_fix = 1, buf_fix_count = 1, buf_pool_index = 0, zip = {data = 0x7fffe8c26000 "", m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 4}, hash = 0x0, free = {prev = 0x7fffe7b95a40, next = 0x0},
  flush_list = {prev = 0x0, next = 0x0}, zip_list = {prev = 0x0, next = 0x0}, newest_modification = 0, oldest_modification = 0, LRU = {prev = 0x7fffe7b95a40, next = 0x7fffe7b95f98}, in_LRU_list = 1, old = 0, freed_page_clock = 0, access_time = 3391528442,
  space_was_being_deleted = 0, is_corrupt = 0, is_compacted = 0}

From recv_recover_page_func:
(gdb) p *block
$6 = {page = {space = 24, offset = 3, state = 5, flush_type = 0, io_fix = 1, buf_fix_count = 1, buf_pool_index = 0, zip = {data = 0x7fffe8c26000 "", m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 4}, hash = 0x0, free = {prev = 0x7fffe7b95a40, next = 0x0},
    flush_list = {prev = 0x0, next = 0x0}, zip_list = {prev = 0x0, next = 0x0}, newest_modification = 0, oldest_modification = 0, LRU = {prev = 0x7fffe7b95a40, next = 0x7fffe7b95f98}, in_LRU_list = 1, old = 0, freed_page_clock = 0, access_time = 3391528442,
    space_was_being_deleted = 0, is_corrupt = 0, is_compacted = 0}, frame = 0x7fffe8c20000 "", unzip_LRU = {prev = 0x7fffe7b95f98, next = 0x7fffe7b95a40}, in_unzip_LRU_list = 1, mutex = {event = 0x10b04a0, lock_word = 0 '\000', waiters = 0, list = {
      prev = 0x7fffe7b95e90, next = 0x7fffe7b95b00}, count_os_wait = 0, cmutex_name = 0x55a471 "&block->mutex", pfs_psi = 0x0}, lock = {lock_word = -1048576, waiters = 0, recursive = 1, writer_thread = 140737198937856, event = 0x10b0520,
    wait_ex_event = 0x10b05a0, list = {prev = 0x7fffe7b95ed0, next = 0x7fffe7b95b40}, pfs_psi = 0x0, count_os_wait = 0, lock_name = 0x55a47f "&block->lock", last_s_file_name = 0x571cf0 "not yet reserved",
    last_x_file_name = 0x564ec0 "/mnt/xb-2.1-valgrind/Percona-Server-5.5/storage/innobase/log/log0recv.c", writer_is_wait_ex = 0, last_s_line = 0, last_x_line = 1580}, lock_hash_val = 28467, check_index_page_at_flush = 0, modify_clock = 0, n_hash_helps = 0,
  n_fields = 1, n_bytes = 0, left_side = 1, is_hashed = 0, curr_n_fields = 0, curr_n_bytes = 0, curr_left_side = 0, index = 0x0, btr_search_latch = 0x0}

(gdb) x/128bx (page)
0x7fffe8c20000: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20008: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20010: 0x00 0x00 0x00 0x00 0x1b 0x7e 0x25 0x66
0x7fffe8c20018: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20020: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20028: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20030: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20038: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20040: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20048: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
0x7fffe8c20050: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
...

Read more...

George -

If that would help somehow, we have redo log and page dumper utility at
lp:~sergei.glushchenko/+junk/percona-pprint

Vlad Lesin (vlad-lesin) wrote :

>OK, the memory corruption seems that it was gdb/optimizations. After building XB and mini-InnoDB with optimizations off, the recv_addr and others look much more rational. Now...

I do not think so because when I reproduced the bug with disabled optimization I saw log records list is corrupted. So I think we should not exclude memory corruption. We need test case that reproduce the bug consistently to explore it more deeply.

> Something is out of sync between the bpage read in the buf_page_io_complete and the actual page...

*.delta file for space 24 is null-filled and data file that corresponds to space 24 is absent in base backup. That means space 24 was created between base and first incremental backups.

Maybe the steps that create space in server runtime differ from the steps that are reproduced during log recovery.

Vlad Lesin (vlad-lesin) wrote :

The assertion is activated during incremental backup preparing. The tablespace on which assertion is activated is created in xb_space_create_file() . FIL_IBD_FILE_INITIAL_SIZE * UNIV_PAGE_SIZE bytes are reserved in the beginning of .ibd file and only the first page is initialized and flushed, the other pages are null and PAGE_N_HEAP field is null too for that pages. During recovery process that null pages are read from .idb file and log records list for the page on which assertion arises begins with several MLOG_ZIP_WRITE_BLOB_PTR log records and MLOG_COMP_REC_INSERT which checks PAGE_N_HEAP field. As the table is compressed and PAGE_N_HEAP is not set for the page the assertion fails.

The base backup does not contain the .idb file. I.e. the .idb file was created between base and first incremental backup. .delta file for the tablespace is null (except header). That means there are no pages in the .idb file with LSN > base backup last lsn. That can be if pages in the .idb file were not flushed at the moment of .delta file generating.

The PAGE_N_HEAP should be set in page_create() which is invoked if MLOG_PAGE_CREATE log record is applied. But log records list does not contain MLOG_PAGE_CREATE for the page. So the main question - why?

Vlad Lesin (vlad-lesin) wrote :

So the crash on "prepare" step happens due to bad generated data on "backup" step. That is why I tried to make the test which would generate such data that would lead to the bug on "prepare" step. I tried the following things:

1) Test with randgen - just launch randgen with percona_qa rules and do incremental backup. The test is attached to this post;

2) buf_flush_list() was modified such a way that it just returns if certain global variable is set, the variable was set just after fil_create_new_single_table_tablespace() was invoked for the newly created compressed table to avoid pages flushing after the tablespace creating, in this case page's recv list contained MLOG_PAGE_CREATE command which invokes page_create_low() and set PAGE_N_HEAP field so the bug was not reproduced.

It seems log file begins to be tracked from wrong start_lsn, but I don't have the ideas how it can be reproduced.

Vlad Lesin (vlad-lesin) wrote :
Download full text (4.8 KiB)

I used percona-redo(lp:~laurynas-biveinis/percona-server/percona-redo) to check once more that log-file in incremental backup direcroty does not contain MLOG_PAGE_CREATE command for the space-page on which the assertion failed. Here is the result (the first several lines of precona-redo output):

{LSN: 17242, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 7729, zip_offset: 7982, blob_ptr: 00 00 00 18 00 00 00 5B 00 00 00 0C 00 00 00 00 00 00 FF FF}
{LSN: 25776, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5280, zip_offset: 8062, blob_ptr: 00 00 00 18 00 00 01 01 00 00 00 0C 00 00 00 00 00 00 00 00}
{LSN: 34318, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5280, zip_offset: 8062, blob_ptr: 00 00 00 18 00 00 01 01 00 00 00 0C 00 00 00 00 00 00 2C 30}
{LSN: 42836, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 7671, zip_offset: 8022, blob_ptr: 00 00 00 18 00 00 01 03 00 00 00 0C 00 00 00 00 00 00 00 00}
{LSN: 51378, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 7671, zip_offset: 8022, blob_ptr: 00 00 00 18 00 00 01 03 00 00 00 0C 00 00 00 00 00 00 2C 30}
{LSN: 59896, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5241, zip_offset: 8082, blob_ptr: 00 00 00 18 00 00 01 05 00 00 00 0C 00 00 00 00 00 00 14 4E}
{LSN: 68430, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 5300, zip_offset: 8042, blob_ptr: 00 00 00 18 00 00 01 06 00 00 00 0C 00 00 00 00 00 00 14 4E}
{LSN: 72057, len: 528, type: MLOG_COMP_REC_INSERT, singlerec: 1, space: 24, page: 3, offset: 2807, end_seg_len: 657, info_status_bits: 0x0, origin_offset: 71, mismatch_index: 0, data: 14 C0 03 01 01 01 00 01 04 14 C0 01 01 01 01 01 01 03 02 04 01 01 01 01 01 01 03 14 C0 01 01 01 01 01 01 04 01 14 C0 01 01 01 03 00 01 05 01 02 01 01 01 01 04 01 01 01 00 01 00 00 00 00 00 C0 12 06 00 00 20 D7 0B 80 00 00 0B 00 00 00 00 05 27 A8 00 00 01 6C 01 28 8F A3 1C 00 00 00 06 64 70 7A 73 8F A9 02 74 68 65 72 65 F3 79 00 00 61 62 69 66 68 8F AA 90 62 65 67 8F A0 D7 8F AD 73 64 6F 6E 27 74 6F 66 64 69 64 61 62 33 06 00 00 67 62 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 68 6C 6F 6F 6B 6A 68 00 00 00 02 61 67 61 00 00 00 00 66 68 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 63 61 6E 80 00 00 09 80 00 00 01 00 00 00 00 72 72 64 C0 45 00 00 74 6A 6C 6B 62 61 63 6B 61 74 61 72 65 63 00 00 00 06 00 00 00 00 64 8F A5 8B 63 62 6B 73 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 6D 65 61 6E 74 00 00 00 05 63 61 78 00 00 80 00 00 08 70 70 73 65 65 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 72 80 00 00 00 68}
{LSN: 81107, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 10672, zip_offset: 7947, blob_ptr: 00 00 00 18 00 00 01 07 00 00 00 0C 00 00 00 00 00 00 00 00}
{LSN: 132192, len: 27, type: MLOG_ZIP_WRITE_BLOB_PTR, singlerec: 0, space: 24, page: 3, offset: 10672, zip_offset: 7947, blob_ptr: 00 00 00 18 00 00 01 07 00 00 00 0C 00 00 00 00 00 00 FF FF}
{LSN: 140710, len: 2...

Read more...

What is the page type for the page 3 in the tablespace? Is it INDEX or something else? If yes, then, then MLOG_PAGE_CREATE should have been written for it. If something else, then no.

Vlad Lesin (vlad-lesin) wrote :

If we would have repeatable test case we could check if LSN of MLOG_PAGE_CREATE command for the (space, page) pair is greater then the last checkpoint LSN. If so then the issue is in wrong start LSN calculation inside of xtrabackup, otherwise the issue is in innodb engine because the page was not flushed on checkpoint.

Vlad, if you want to insert some extra debug logging into the XB InnoDB
code we have a sort of easy way to do that, the we can re-run the test
case that eventually reproduces the issue on backup and watch the logs.

On 6/10/2013 12:15 AM, Vlad Lesin wrote:
> If we would have repeatable test case we could check if LSN of
> MLOG_PAGE_CREATE command for the (space, page) pair is greater then the
> last checkpoint LSN. If so then the issue is in wrong start LSN
> calculation inside of xtrabackup, otherwise the issue is in innodb
> engine because the page was not flushed on checkpoint.
>

--
George O. Lorch III
Software Engineer, Percona
+1-888-401-3401 x542 US/Arizona (GMT -7)
skype: george.ormond.lorch.iii

Alexey Kopytov (akopytov) wrote :

I think the root cause here is that xb_data_files_init() (i.e. loading tablespaces into fil_system) is performed before log copying is started.

Consider the following scenario:

When the full backup is started:

- the server starts to execute CREATE/ALTER TABLE
- xb_data_files_init() is called from xtrabackup_backup_func()
- if the file for the newly created tablespace already exists (i.e. is seen by fil_load_single_tablespaces()), but the first page has not been initialized/flushed yet, xtrabackup complains about tablespace ID being nonsensical and omits the table from the full backup
- the server writes MLOG_FILE_CREATE (and possibly other records corresponding to that tablespace) to the log and performs a checkpoint
- xtrabackup starts copying the log later in xtrabackup_backup_func(), so it will not write MLOG_FILE_CREATE to xtrabackup_logfile

When the incremental backup is started:

- if the corresponding page updates in the tablespace have not been flushed yet, we generate an empty delta for it
- and copy the corresponding updates to the incremental log file

When the full backup is prepared:

- we ignore all possible log records corresponding to the tablespace, because it doesn't exist (and there's no MLOG_FILE_CREATE in the log, so it is not created on prepare)

When the incremental backup is applied:

- xb_delta_open_matching_space() creates a new tablespace assuming the table was created between the full and incremental backups
- xtrabackup then starts to apply log records to uninitialized pages

Alexey Kopytov (akopytov) wrote :

Stealing this as the fix is related to bug #1187071 and will be fixed in the same commit.

tags: added: ptb
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Bug attachments