Percona XtraBackup moved to https://jira.percona.com/projects/PXB

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

Bug #1177201 reported by George Ormond Lorch III
22
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Fix Released
High
Alexey Kopytov
Percona XtraBackup moved to https://jira.percona.com/projects/PXB 2.2.0
2.1
Fix Released
High
Alexey Kopytov
Percona XtraBackup moved to https://jira.percona.com/projects/PXB 2.1.8
2.2
Fix Released
High
Alexey Kopytov
Percona XtraBackup moved to https://jira.percona.com/projects/PXB 2.2.0

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.

Tags: i37628

Related branches

lp:~akopytov/percona-xtrabackup/bug1177201-2.1
Alexey Kopytov (community): Approve
Sergei Glushchenko (community): Approve (g2)
Diff: 59 lines (+43/-0)
2 files modified
src/fil_cur.cc (+21/-0)
test/t/bug1177201.sh (+22/-0)
Sergei Glushchenko (community): Needs Resubmitting (g2)
Diff: 54 lines (+38/-0)
2 files modified
storage/innobase/xtrabackup/src/fil_cur.cc (+16/-0)
storage/innobase/xtrabackup/test/t/bug1177201.sh (+22/-0)
lp:~akopytov/percona-xtrabackup/bug1177201-2.2
Alexey Kopytov (community): Approve
Sergei Glushchenko (community): Approve (g2)
Diff: 59 lines (+43/-0)
2 files modified
storage/innobase/xtrabackup/src/fil_cur.cc (+21/-0)
storage/innobase/xtrabackup/test/t/bug1177201.sh (+22/-0)
Revision history for this message
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
Revision history for this message
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

Revision history for this message
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.

Revision history for this message
Alexey Kopytov (akopytov) wrote :

Also occurs in Jenkins: http://jenkins.percona.com/job/percona-xtrabackup-2.1-param/435/BUILD_TYPE=release,Host=centos5-64,xtrabackuptarget=xtradb56/testReport/junit/%28root%29/t_ib_stream_incremental/sh/

Revision history for this message
Andrew Gaul (gaul) wrote :

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

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

Ovais Tariq (ovais-tariq)
tags: added: i37628
Alexey Kopytov (akopytov)
no longer affects: percona-xtrabackup/2.0
Revision history for this message
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?

Revision history for this message
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.

Revision history for this message
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.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

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

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.