Problem PREPARING incremental backup

MySQL & MariaDB Percona XtraBackup
1

I’m testing out Percona XtraBackup 2.2 and ran into a problem the first time I tried to restore an incremental backup. I assume I’ve done something wrong; hopefully someone can tell me what that is, I’ve included all the details below.

Executive Summary:

The PREPARE of the first incremental backup fails with the following error:
2015-01-30 14:33:35 b735b700 InnoDB: Error: space id and page n:o stored in the page
InnoDB: read in are 0:524293, should be 0:5!

Operating System = Ubuntu 14.04.01 (Bitnami Tomcat Stack)
Database = MySQL 5.5.38

Backup Steps

  1. Start up a virtual machine (V1) from image (V) and log in
  2. Create a full backup (B) of the database:

==> Successful, creates directory 2015-01-30_10-44-37

  1. Add a few records to the database
  2. Create an incremental backup (b1) of the database

==> Successful, creates directory 2015-01-30_10-59-30

  1. Add a few more records to the database
  2. Create an incremental backup (b2) of the database

==> Successful, creates directory 2015-01-30_11-06-54

  1. Disconnect the disk (D) with these backups on it from V1.

Restore Steps

My first testcase was to do a point in time restore the database on a new virtual machine V2 to the state after the first incremental backup (b1)

  1. Start up another virtual machine (V2) from image (V) and log in
  2. Connect the disk (D) to (V2).
  3. Prepare the base backup (B)

==> Works OK

  1. Prepare the incremental backup (b1)

==> At this point I get an error:

xtrabackup version 2.2.8 based on MySQL server 5.6.22 Linux (i686) (revision id: )
incremental backup from 19492498688 is enabled.
xtrabackup: cd to /mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(19492581719)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Generating a list of tablespaces
xtrabackup: page size for /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30/ibdata1.delta is 16384 bytes
Applying /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30/ibdata1.delta to ./ibdata1…
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
2015-01-30 14:33:35 b735b700 InnoDB: Error: space id and page n:o stored in the page
InnoDB: read in are 0:524293, should be 0:5!
2015-01-30 14:33:35 b735b700 InnoDB: Assertion failure in thread 3073750784 in file srv0start.cc line 1373
InnoDB: Failing assertion: prev_space_id + 1 == undo_tablespace_ids[i]
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: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: about forcing recovery.
19:33:35 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0xab7ff60
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong…
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x2d) [0x85a011d]
xtrabackup(handle_fatal_signal+0x270) [0x8439be0]
[0xb7760400]
[0xb7760424]
/lib/i386-linux-gnu/libc.so.6(gsignal+0x47) [0xb738b827]
/lib/i386-linux-gnu/libc.so.6(abort+0x143) [0xb738ec53]
xtrabackup(srv_undo_tablespaces_init(unsigned long, unsigned long, unsigned long, unsigned long*)+0x6a8) [0x8207ff8]
xtrabackup(innobase_start_or_create_for_mysql()+0xd86) [0x8208eb6]
xtrabackup() [0x81adde7]
xtrabackup(main+0x173f) [0x8197f8f]
/lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xf3) [0xb7376a83]
xtrabackup() [0x81ab151]

Please report a bug at [url]https://bugs.launchpad.net/percona-xtrabackup[/url]
innobackupex: got a fatal error with the following stacktrace: at /usr/bin/innobackupex line 2633.
main::apply_log() called at /usr/bin/innobackupex line 1561
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2633.

2

Hi chrisodd;

Percona has a nice guide for this as it is a bit confusing:
[url]Percona XtraBackup

For step 11 you need to add --redo-only, and then after that you will do a full --apply-log to the base backup.

-Scott

3

Hi Scott,

That guide is exactly what I was using. Since I’m trying to restore only B + b1, the incremental b1 is the LAST incremental I will be restoring in this test case. It looked to me like I shouldn’t be using --redo-only with that one; from the guide you reference:
should be used when merging all incrementals except the last one.
However, it also looks like using the --redo-only flag won’t hurt either:

So I decided to try adding the --redo-only flag to the first incremental anyway, as you recommend.

I restored the backup disk to it’s post (Step 7) state (I’m doing all of this on AWS and had snapshotted that disk at that point last time, so it’s easy), then reran the commands, but I get the same error.

Here’s the log showing the results: (the commands differ slightly from the first iteration as I realized this time around that I could omit the --defaults-file, --user, and --password flags when preparing the restore):

NOTE: when I look at this post there is a happy face emoticon in the log, this is really supposed to be a “:” and an “o”.

root@ip-xx-xx-xx-xx:/mnt/SQL# /usr/bin/innobackupex --apply-log --redo-only /mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

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

Get the latest version of Percona XtraBackup, documentation, and help resources:
[url]Percona XtraBackup - MySQL Database Backup Software

150131 11:22:51 innobackupex: Starting the apply-log operation

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

150131 11:22:51 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file=“/mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37/backup-my.cnf” --defaults-group=“mysqld” --prepare --target-dir=/mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37 --apply-log-only

xtrabackup version 2.2.8 based on MySQL server 5.6.22 Linux (i686) (revision id: )
xtrabackup: cd to /mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(19492497596)
xtrabackup: using the following InnoDB configuration for recovery:
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 = 2097152
xtrabackup: using the following InnoDB configuration for recovery:
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 = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 19492497596
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files…
InnoDB: Restoring possible half-written data pages
InnoDB: from the doublewrite buffer…
InnoDB: Doing recovery: scanned up to log sequence number 19492498688 (0%)
InnoDB: Starting an apply batch of log records to the database…
InnoDB: Progress in percent: 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 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

[notice (again)]
If you use binary log and don’t use any hack of group commit,
the binary log position seems to be:

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
InnoDB: Starting shutdown…
InnoDB: Shutdown completed; log sequence number 19492498688
150131 11:22:57 innobackupex: completed OK!
root@ip-xx-xx-xx-xx:/mnt/SQL# /usr/bin/innobackupex --apply-log --redo-only /mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37 --incremental-dir=/mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

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

Get the latest version of Percona XtraBackup, documentation, and help resources:
[url]Percona XtraBackup - MySQL Database Backup Software

150131 11:23:33 innobackupex: Starting the apply-log operation

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

150131 11:23:33 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file=“/mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37/backup-my.cnf” --defaults-group=“mysqld” --prepare --target-dir=/mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37 --apply-log-only --incremental-dir=/mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30

xtrabackup version 2.2.8 based on MySQL server 5.6.22 Linux (i686) (revision id: )
incremental backup from 19492498688 is enabled.
xtrabackup: cd to /mnt/mySQLDumps/BackupTesting/2015-01-30_10-44-37
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(19492581719)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Generating a list of tablespaces
xtrabackup: page size for /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30/ibdata1.delta is 16384 bytes
Applying /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30/ibdata1.delta to ./ibdata1…
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_data_home_dir = ./
xtrabackup: innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup: innodb_log_group_home_dir = /mnt/mySQLDumps/BackupTesting/2015-01-30_10-59-30
xtrabackup: innodb_log_files_in_group = 1
xtrabackup: innodb_log_file_size = 2097152
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: Using atomics to ref count buffer pool pages
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Memory barrier is not used
InnoDB: Compressed tables use zlib 1.2.8
InnoDB: Not using CPU crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
2015-01-31 11:23:36 b73a7700 InnoDB: Error: space id and page n:o stored in the page
InnoDB: read in are 0:524293, should be 0:5!
2015-01-31 11:23:36 b73a7700 InnoDB: Assertion failure in thread 3074062080 in file srv0start.cc line 1373
InnoDB: Failing assertion: prev_space_id + 1 == undo_tablespace_ids[i]
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: [url]http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html[/url]
InnoDB: about forcing recovery.
16:23:36 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Thread pointer: 0x95bdf60
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong…
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x2d) [0x85a011d]
xtrabackup(handle_fatal_signal+0x270) [0x8439be0]
[0xb77ac400]
[0xb77ac424]
/lib/i386-linux-gnu/libc.so.6(gsignal+0x47) [0xb73d7827]
/lib/i386-linux-gnu/libc.so.6(abort+0x143) [0xb73dac53]
xtrabackup(srv_undo_tablespaces_init(unsigned long, unsigned long, unsigned long, unsigned long*)+0x6a8) [0x8207ff8]
xtrabackup(innobase_start_or_create_for_mysql()+0xd86) [0x8208eb6]
xtrabackup() [0x81adde7]
xtrabackup(main+0x173f) [0x8197f8f]
/lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xf3) [0xb73c2a83]
xtrabackup() [0x81ab151]

Please report a bug at [url]https://bugs.launchpad.net/percona-xtrabackup[/url]
innobackupex: got a fatal error with the following stacktrace: at /usr/bin/innobackupex line 2633.
main::apply_log() called at /usr/bin/innobackupex line 1561
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/innobackupex line 2633.

4

Hi chrisodd;

Yeah that is strange. Could potentially be a bug since you are using 5.6, as I’ve seen various random errors related to 5.6. Are the Xtrabackup and MySQL versions the same on both VMs?

If it was me I’d try some different cases to narrow down where the problem is. First I’d try leaving the disk attached to the original VM and see if you can do the incremental prepare there. Second I’d do just a plain “base” backup and try to prepare that on the original VM and the second VM. After those two tests, you’ll then be able to determine if the problem has anything to do with the swapping between VMs or if it is related to the incremental backup steps.

-Scott

5

The Xtrabackup and MySQL versions are identical on both VMs. The two VMs were generated from the same image and at the beginning of the test case are identical in every way except for their IP address.

The plain base backup prepares and restores just fine.

I deleted the initial VM so I can’t do the incremental prepare there, but since the two VMs are identical I doubt there would be any difference in behaviour. That said, I think my next step will be to start over and see if this is consistently reproducible (and if it is, I will try doing the prepare on the first “source” VM to see if it makes any difference).

I’m curious when you say “Could potentially be a bug since you are using 5.6”. What software are you referring to? MySQL version is 5.5.38.

6

Hi chrisodd;

Ah yeah did not see you were running 5.5. I saw the “version 2.2.8 based on MySQL server 5.6.22 Linux (i686)” message in the backup text and started thinking you were on 5.6.

One thing you might try is specifying --ibbackup=xtrabackup_55 when you take the backup and when you restore it and see if that makes a difference.

[url]The innobackupex Option Reference

-Scott