Assertion in file rem0rec.c line 561 when restoring incremental using changed page bitmaps

Bug #1113073 reported by George Ormond Lorch III
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Incomplete
Undecided
George Ormond Lorch III

Bug Description

Testing XB branch ~laurynas-biveinis/percona-xtrabackup/BT-16274-xtrabackup-changed-page-tracking against PS branch ~laurynas-biveinis/percona-server/QA-16724-5.5-2

Use my.cnf:
[client]
port=5528
socket=/data/dev/16274/2/1/mysql.sock
[mysqld]
basedir=/usr/local/dev/ps-5.5-16274
datadir=/data/dev/16274/2/1/data
tmpdir=/data/dev/16274/2/1/tmp
port=5528
socket=/data/dev/16274/2/1/mysql.sock
pid-file=/data/dev/16274/2/1/mysql.pid
console
user=root
server-id=1
innodb_track_changed_pages=TRUE
innodb_buffer_pool_size=2G
innodb_log_file_size=500M

Start server and RQG against server with percona_qa grammer.

Perform a baseline 'full' backup:
innobackupex --defaults-file=... --ibbackup=xtrabackup --no-timestamp ./0
then loop, creating successive incrementals:
for (( i=1; i < 20; i++ ))
do
    sleep 40 # or 10 or 20 or 30, depends on machine speed and debug, with full debug I need 40, in release 10 is enough
    local prev=`expr $i - 1`
    innobackupex --defaults-file=... --ibbackup=xtrabackup --no-timestamp --incremental ./$i --incremental-basedir=./$prev
done

Shutdown the server.

Now start the restoration process:
mkdir ./working
innobackupex --defaults-file=... --ibbackup=xtrabackup --apply-log --redo-only ./0
innobackupex --defaults-file=... --ibbackup=xtrabackup --apply-log --redo-only ./0 --incremental-dir=./1
innobackupex --defaults-file=... --ibbackup=xtrabackup --apply-log --redo-only ./0 --incremental-dir=./2
etc...

Along this process, you will get an assertion from xtrabackup:
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 130201 19:03:11 InnoDB: Assertion failure in thread 140550848112384 in file rem0rec.c line 561
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 /data/bin/xb-2.1-16274-5.5/innobackupex line 383.

core backtrace:
#0 0x000000391a8328a5 in raise () from /lib64/libc.so.6
#1 0x000000391a834085 in abort () from /lib64/libc.so.6
#2 0x00000000004c2f71 in rec_get_offsets_func (rec=0x7fd4819f00bb "", index=0x7fd478001e28, offsets=0x7fd48b5fd480, n_fields=18446744073709551615, heap=0x7fd48b5fd7a8,
    file=0x592168 "/home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/page/page0cur.c", line=1850) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/rem/rem0rec.c:561
#3 0x00000000004ae87d in page_cur_parse_delete_rec (ptr=0x7fd484b5460a "", end_ptr=0x7fd484b5460a "", block=0x7fd48099dc80, index=0x7fd478001e28, mtr=0x7fd48b5fd880) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/page/page0cur.c:1849
#4 0x0000000000499e67 in recv_parse_or_apply_log_rec_body (type=42 '*', ptr=0x7fd484b54608 "", end_ptr=0x7fd484b5460a "", block=0x7fd48099dc80, mtr=0x7fd48b5fd880) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/log/log0recv.c:1247
#5 0x000000000049a959 in recv_recover_page_func (just_read_in=1, block=0x7fd48099dc80) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/log/log0recv.c:1666
#6 0x00000000004402cb in buf_page_io_complete (bpage=0x7fd48099dc80) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/buf/buf0buf.c:4065
#7 0x000000000046f19f in fil_aio_wait (segment=5) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/fil/fil0fil.c:5739
#8 0x00000000004f7cd7 in io_handler_thread (arg=0xa78348) at /home/glorch/dev/xb-2.1-16274-5.5/Percona-Server-5.5/storage/innobase/srv/srv0start.c:485
#9 0x000000391b007851 in start_thread () from /lib64/libpthread.so.0
#10 0x000000391a8e811d in clone () from /lib64/libc.so.6

Tags: qa
Revision history for this message
George Ormond Lorch III (gl-az) wrote :

core dump

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

See also comment from "[1 Feb 2:25]" in http://bugs.mysql.com/bug.php?id=68222 (identical assertion failure in MEB).

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

George -

Does this error happen with the slow incremental backups too?

Revision history for this message
George Ormond Lorch III (gl-az) wrote :

laurynas,
I have had the test running for about 3 hours now (10 full iterations of base full + 20 incremental backups) using the exact same binaries and configuration except I removed the innodb_track_changed_pages and could not reproduce. Adding that back in it reproduces almost immediately. While this creates a reasonable correlation that the CPB feature is to blame it does not totally confirm it. It could simply be that CPB aggravates the existing root cause in my particular environment.

If there is any extra diagnostic code that you would like me to inject, feel free to suggest it and I can rebuild and retest.

tags: added: qa
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

I have fixed a bug in the XB branch that could have caused a failure to copy some of the required data pages (and also cause copying some of the non-required data pages). Let's see if the failure is reproducible now?

Changed in percona-xtrabackup:
assignee: Laurynas Biveinis (laurynas-biveinis) → George Ormond Lorch III (gl-az)
Changed in percona-xtrabackup:
status: New → In Progress
no longer affects: percona-xtrabackup/2.1
no longer affects: percona-xtrabackup/2.0
Changed in percona-xtrabackup:
status: In Progress → Incomplete
Changed in percona-xtrabackup:
importance: High → Undecided
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-1199

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

Other bug subscribers

Bug attachments

Remote bug watches

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