Assertion "to_read % cursor->page_size == 0" failed at fil_cur.cc:218

Reported by George Ormond Lorch III on 2013-05-07
18
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona XtraBackup
Status tracked in 2.2
2.1
High
Alexey Kopytov
2.2
High
Alexey Kopytov

Bug Description

Running RQG in a loop against PS 5.5 with XB 2.1 using the Percona Test Bench. While performing incremental backup:

XtraBackup options: parallel=2
XtraBackup command: --defaults-file=/mnt/var/cpb/test-4/mysql.1/my.cnf --no-timestamp --tmpdir=/mnt/var/cpb/test-4 --incremental --incremental-basedir=/mnt/var/cpb/test-4/backup-1.2

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.

130507 03:26:18 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_file=/mnt/var/cpb/test-4/mysql.1/my.cnf;mysql_read_default_group=xtrabackup' (using password: NO).
130507 03:26:18 innobackupex: Connected to MySQL server
IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackupex
           prints "completed OK!".

innobackupex: Using mysql server version 5.5.30

innobackupex: Created backup directory /mnt/var/cpb/test-4/backup-1.3

130507 03:26:18 innobackupex: Starting ibbackup with command: xtrabackup_55 --defaults-file="/mnt/var/cpb/test-4/mysql.1/my.cnf" --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/mnt/var/cpb/test-4/backup-1.3 --tmpdir=/mnt/var/cpb/test-4 --incremental-basedir='/mnt/var/cpb/test-4/backup-1.2'
innobackupex: Waiting for ibbackup (pid=29907) to suspend
innobackupex: Suspend file '/mnt/var/cpb/test-4/backup-1.3/xtrabackup_suspended_2'

xtrabackup_55 version 2.1.0beta1 for Percona Server 5.5.16 Linux (x86_64) (revision id: undefined)
incremental backup from 1595905858 is enabled.
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /mnt/var/cpb/test-4/mysql.1/data
xtrabackup: Target instance is assumed 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 = 2
xtrabackup: innodb_log_file_size = 536870912
130507 3:26:19 InnoDB: Warning: allocated tablespace 2204, old maximum was 9
>> log scanned up to (1641095963)
xtrabackup: using the full scan for incremental backup
[01] Copying ./ibdata1 to /mnt/var/cpb/test-4/backup-1.3/ibdata1.delta
[01] ...done
[01] Copying ./rqg1/table500_innodb_default_int.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/table500_innodb_default_int.ibd.delta
[01] ...done
[01] Copying ./rqg1/c.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/c.ibd.delta
[01] ...done
[01] Copying ./rqg1/table500_innodb_default_int_autoinc.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/table500_innodb_default_int_autoinc.ibd.delta
[01] ...done
^Gxtrabackup_55: Can't get stat of './rqg1/w.ibd' (Errcode: 2)
[01] xtrabackup: Warning: cannot stat ./rqg1/w.ibd
[01] xtrabackup: Warning: We assume the table was dropped during xtrabackup execution and ignore the file.
[01] xtrabackup: Warning: skipping tablespace ./rqg1/w.ibd.
[01] Copying ./rqg1/table100_innodb_default.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/table100_innodb_default.ibd.delta
[01] ...done
[01] Copying ./rqg1/o.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/o.ibd.delta
[01] ...done
[01] Copying ./rqg1/y.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/y.ibd.delta
[01] ...done
[01] Copying ./rqg1/table100_innodb_default_int_autoinc.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/table100_innodb_default_int_autoinc.ibd.delta
[01] ...done
>> log scanned up to (1643014497)
[01] Copying ./rqg1/table500_innodb_default.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/table500_innodb_default.ibd.delta
[01] ...done
[01] Copying ./rqg1/table100_innodb_default_int.ibd to /mnt/var/cpb/test-4/backup-1.3/rqg1/table100_innodb_default_int.ibd.delta
Assertion "to_read % cursor->page_size == 0" failed at fil_cur.cc:218
innobackupex: Error: ibbackup child process has died at /mnt/bin/xb-2.1/innobackupex line 386.
DBD::mysql::db selectrow_array failed: MySQL server has gone away at /mnt/bin/xb-2.1/innobackupex line 1322.

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

Backtrace:

Thread 13 (Thread 0x7fc30b9f8700 (LWP 29918)):
#0 0x00007fc31692543c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004ae899 in os_cond_wait (event=0x18edbb0, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x18edbb0, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:609
#3 0x00000000004abb79 in os_aio_simulated_handle (global_segment=9, message1=0x7fc30b9f7e68, message2=0x7fc30b9f7e60, type=0x7fc30b9f7e58, space_id=0x7fc30b9f7e50) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0file.c:5097
#4 0x0000000000474354 in fil_aio_wait (segment=9) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5701
#5 0x000000000040a018 in io_handler_thread (arg=<value optimized out>) at xtrabackup.cc:2276
#6 0x00007fc316921851 in start_thread () from /lib64/libpthread.so.0
#7 0x00007fc315ccb90d in clone () from /lib64/libc.so.6

Thread 12 (Thread 0x7fc30cdfa700 (LWP 29916)):
#0 0x00007fc31692543c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004ae899 in os_cond_wait (event=0x18edab0, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x18edab0, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:609
#3 0x00000000004abb79 in os_aio_simulated_handle (global_segment=7, message1=0x7fc30cdf9e68, message2=0x7fc30cdf9e60, type=0x7fc30cdf9e58, space_id=0x7fc30cdf9e50) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0file.c:5097
#4 0x0000000000474354 in fil_aio_wait (segment=7) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5701
#5 0x000000000040a018 in io_handler_thread (arg=<value optimized out>) at xtrabackup.cc:2276
#6 0x00007fc316921851 in start_thread () from /lib64/libpthread.so.0
#7 0x00007fc315ccb90d in clone () from /lib64/libc.so.6

Thread 11 (Thread 0x7fc30aff7700 (LWP 29919)):
#0 0x00007fc3169257bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004ae753 in os_cond_wait_timed (event=0x19054a0, time_in_usec=1000000, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:171
#2 os_event_wait_time_low (event=0x19054a0, time_in_usec=1000000, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:716
#3 0x000000000040c412 in log_copying_thread (arg=<value optimized out>) at xtrabackup.cc:2199
#4 0x00007fc316921851 in start_thread () from /lib64/libpthread.so.0
#5 0x00007fc315ccb90d in clone () from /lib64/libc.so.6

Thread 10 (Thread 0x7fc30e1fc700 (LWP 29914)):
#0 0x00007fc31692543c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00000000004ae899 in os_cond_wait (event=0x18ed9b0, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x18ed9b0, reset_sig_count=1) at /mnt/xb-2.1/Percona-Server-5.5/storage/innobase/os/os0sync.c:609
#3 0x00000000004abb79 in os_aio_simulated_handle (global_segment=5, message1=0x7fc30e1fbe68, message2=0x7fc30e1fbe60, type=0x7...

Changed in percona-xtrabackup:
status: New → Incomplete
George Ormond Lorch III (gl-az) wrote :

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
innodb_track_changed_pages=FALSE

Alexey Kopytov (akopytov) wrote :

It is possible when a tablespace is being extended while we get the file size before copying. I think we should handle it like a partial page write during copy, i.e. make sure the file size is a multiple of page size and retry stat() if it is not.

Andrew Gaul (gaul) wrote :

Possible cause of bogus trailing zeros and non-page size file sizes:

https://bugs.launchpad.net/percona-server/+bug/1262500

tags: added: i37628
no longer affects: percona-xtrabackup/2.0
Paul Namuag (paul-namuag) wrote :

Could it be same as the concern I posted here, http://www.mysqlperformanceblog.com/2013/11/27/percona-xtrabackup-a-workaround-for-failed-assertion-bug/? Does running ALTER TABLE ... ENGINE=InnoDB can partially alleviate the bug?

Ovais Tariq (ovais-tariq) wrote :

Rebulding the tablespace should resolve the issue but that is not always doable in case you have a very big dataset or in case the system tablespace is affected.

What I and Alexey have been discussing is that since InnoDB handles tables with partial pages just fine and does not complain, hence XB should also be able to handle tablespaces with partial pages as well. So may be it should either not have this assertion, or it should try the page read more than 1 time.

Alexey Kopytov (akopytov) wrote :

We also have a report from a user running upstream MySQL 5.5.30. There's a stray 4K block of zeroes appended to the end of ibdata1, which leads to the same assertion failure in XtraBackup. Which probably rules out bug #1262500 as a possible culprit for this issue.

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

Other bug subscribers