applying incremental on backup prepared with innobackupex --apply-log --redo-only fails to update ib_logfile*'s

Reported by Kenny Gryp on 2011-02-11
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup
High
Valentine Gostev

Bug Description

root@lesktop:/data/backups# cat base/xtrabackup_checkpoints
backup_type = full-backuped
from_lsn = 0
to_lsn = 4958825500
root@lesktop:/data/backups# cat inc1/xtrabackup_checkpoints
backup_type = incremental
from_lsn = 4958825500
to_lsn = 4959549393

root@lesktop:/data/backups# innobackupex-1.5.1 --ibbackup=xtrabackup --apply-log --redo-only /data/backups/base/
Version string '' contains invalid data; ignoring: '' at /usr/bin/innobackupex-1.5.1 line 1708.

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy.
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-1.5.1
           prints "completed OK!".

110211 18:30:44 innobackupex-1.5.1: Starting ibbackup with command: xtrabackup --prepare --target-dir=/data/backups/base --apply-log-only

xtrabackup Ver 1.4 Rev 193 for 5.1.47 unknown-linux-gnu (x86_64)
xtrabackup: cd to /data/backups/base
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(4957251392)
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 = ./
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: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Warning: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
110211 18:30:44 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 4957251392
110211 18:30:44 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 4959024440 (95 %)
110211 18:30:46 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 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
InnoDB: Last MySQL binlog file position 0 55271, file name /var/log/mysql/mysql-bin.000117

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 55271, file name /var/log/mysql/mysql-bin.000117

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
110211 18:30:47 InnoDB: Starting shutdown...
110211 18:30:47 InnoDB: Shutdown completed; log sequence number 4959024440

110211 18:30:47 innobackupex-1.5.1: Restarting xtrabackup with command: xtrabackup --prepare --target-dir=/data/backups/base --apply-log-only
for creating ib_logfile*

xtrabackup Ver 1.4 Rev 193 for 5.1.47 unknown-linux-gnu (x86_64)
xtrabackup: cd to /data/backups/base
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
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 = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 5242880
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Warning: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
110211 18:30:47 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
110211 18:30:47 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
110211 18:30:47 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
110211 18:30:47 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Last MySQL binlog file position 0 55271, file name /var/log/mysql/mysql-bin.000117

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 55271, file name /var/log/mysql/mysql-bin.000117

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
110211 18:30:48 InnoDB: Starting shutdown...
110211 18:30:48 InnoDB: Shutdown completed; log sequence number 4959024652
110211 18:30:48 innobackupex-1.5.1: completed OK!

root@lesktop:/data/backups# cat base/xtrabackup_checkpoints
backup_type = full-prepared
from_lsn = 0
to_lsn = 4958825500

root@lesktop:/data/backups# xtrabackup --prepare --apply-log-only --target-dir=/data/backups/base/ --incremental-dir=/data/backups/inc1/
xtrabackup Ver 1.4 Rev 193 for 5.1.47 unknown-linux-gnu (x86_64)
incremental backup from 4958825500 is enabled.
xtrabackup: cd to /data/backups/base/
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
Applying /data/backups/inc1//ibdata1.delta ...
...
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 = /data/backups/inc1/
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 5242880
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: Warning: innodb_file_io_threads is deprecated. Please use innodb_read_io_threads and innodb_write_io_threads instead
110211 18:32:37 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
110211 18:32:37 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Last MySQL binlog file position 0 61013, file name /var/log/mysql/mysql-bin.000117

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 61013, file name /var/log/mysql/mysql-bin.000117

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
110211 18:32:39 InnoDB: Starting shutdown...
110211 18:32:39 InnoDB: Shutdown completed; log sequence number 4960381964

root@lesktop:/data/backups# cat base/xtrabackup_checkpoints
backup_type = full-prepared
from_lsn = 0
to_lsn = 4959549393

as you can see the ibdata file was updated, but the ib_logfile*'s weren't:
root@lesktop:/data/backups# ls -alhs base/ib*
186M -rw-r--r-- 1 root root 186M 2011-02-11 18:32 base/ibdata1
5.0M -rw-r--r-- 1 root root 5.0M 2011-02-11 18:30 base/ib_logfile0
5.0M -rw-r--r-- 1 root root 5.0M 2011-02-11 18:30 base/ib_logfile1

root@lesktop:/data/backups# cp -Rp base/ /var/lib/mysql
root@lesktop:/data/backups# chown -R mysql:mysql /var/lib/mysql

root@lesktop:/data/backups# /etc/init.d/mysql start

Then I get the following in the errorlog:
110211 18:36:11 InnoDB: Initializing buffer pool, size = 128.0M
110211 18:36:11 InnoDB: Completed initialization of buffer pool
110211 18:36:11 InnoDB: highest supported file format is Barracuda.
InnoDB: ##########################################################
InnoDB: WARNING!
InnoDB: The log sequence number in ibdata files is higher
InnoDB: than the log sequence number in the ib_logfiles! Are you sure
InnoDB: you are using the right ib_logfiles to start up the database?
InnoDB: Log sequence number in ib_logfiles is 4959024652, log
InnoDB: sequence numbers stamped to ibdata file headers are between
InnoDB: 4960381964 and 4960381964.
InnoDB: ##########################################################
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
110211 18:36:11 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
110211 18:36:12 InnoDB: Error: page 7 log sequence number 4959531629
InnoDB: is in the future! Current system log sequence number 4959024652.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: for more information.
.....

I would assume this works when reading innobackupex --help:
    --redo-only Options is used with --apply-log. This option forces to skip
                "rollback" phase and do only "redo". This is necessary to use
                if backup later will be applied with incremental changes.

But actually it doesn't.

Either this is a documentation bug and we should not use innobackupex --apply-log --redo-only to prepare a backup where incremental backup has to be replayed against.

Or this is a bug and xtrabackup --prepare --apply-log-only --target-dir=... --incremental-dir=... should update the ib_logfile*'s if they exist already.
At least it should bail out if it does things it should not do.

Alexey Kopytov (akopytov) wrote :

Patch for xb_incremental.sh to reproduce this bug:

=== modified file 'test/t/xb_incremental.sh'
--- test/t/xb_incremental.sh 2010-12-09 09:37:20 +0000
+++ test/t/xb_incremental.sh 2011-02-11 20:02:15 +0000
@@ -60,7 +60,7 @@
 vlog "Preparing backup"

 # Prepare backup
-xtrabackup --datadir=$mysql_datadir --prepare --apply-log-only --target-dir=$topdir/data/full
+innobackupex-1.5.1 --apply-log --redo-only $topdir/data/full
 vlog "Log applied to backup"
 xtrabackup --datadir=$mysql_datadir --prepare --apply-log-only --target-dir=$topdir/data/full --incremental-dir=$topdir/data/delta
 vlog "Delta applied to backup"

Vadim Tkachenko (vadim-tk) wrote :

The problem happens because on --redo-only stage innobackupex script still tries to create log_files. It is not needed.
I have patch with fixes that.
Will commit soon.

Changed in percona-xtrabackup:
assignee: nobody → Vadim Tkachenko (vadim-tk)
status: New → In Progress
importance: Undecided → High
milestone: none → 1.6
Vadim Tkachenko (vadim-tk) wrote :

I proposed merge with fix for this bug, this however changes functionality a little.

The proper workflow to prepare full and apply incremental changes is following

innobackupex --apply-log --redo-only /mnt/tachion/xtrab/fullbackup

innobackupex --apply-log /mnt/tachion/xtrab/fullbackup --incremental-dir=/mnt/tachion/xtrab/incremental

After both of these commands, innobackupex does not create ib_logfile* automatically.

Anyway I do not consider automatic creation of ib_logfile* so much useful.

If you still need to have ib_logfile* in advance you can just execute xtrabackup --prepare on target directory.

These changes should be documented and I assign Baron & Fred for it

Alexey Kopytov (akopytov) wrote :

Is there really a change in the workflow after the fix for this bug? http://www.percona.com/docs/wiki/percona-xtrabackup:xtrabackup:incremental does not mention using innobackupex for incremental backups at all. So the only documented way is to use xtrabackup.

What's different now is that:

1. innobackupex *may* be used now instead of xtrabackup to prepare the full backup.

2. innobackupex *may* be used now instead of xtrabackup to apply the incremental backup. This change is a result of the fixes for this bug and http://bazaar.launchpad.net/~percona-dev/percona-xtrabackup/trunk/revision/218

So to me it looks more like an extension to the documented behavior rather than a change in the workflow.

On 13 Feb 2011, at 11:01, Alexey Kopytov wrote:

> Is there really a change in the workflow after the fix for this bug?
> http://www.percona.com/docs/wiki/percona-
> xtrabackup:xtrabackup:incremental does not mention using innobackupex
> for incremental backups at all. So the only documented way is to use
> xtrabackup.

Alexey, FYI:

the innobackupex-1.5.1 documentation mentioned it was possible:
   --redo-only Options is used with --apply-log. This option forces to skip
               "rollback" phase and do only "redo". This is necessary to use
               if backup later will be applied with incremental changes.

And changelog of 1.4 mentioned that it was possible:
Incremental backups have changed and now allow the restoration of full backups containing certain rollback transactions that previously caused problems. Please see Preparing the Backupsand the --apply-log-only option. (From innobackupex, the --redo-only option should be used). (Yasufumi Kinoshita) (http://www.mysqlperformanceblog.com/2010/11/22/percona-xtrabackup-1-4/)

>
> What's different now is that:
>
> 1. innobackupex *may* be used now instead of xtrabackup to prepare the
> full backup.
>
> 2. innobackupex *may* be used now instead of xtrabackup to apply the
> incremental backup. This change is a result of the fixes for this bug
> and http://bazaar.launchpad.net/~percona-dev/percona-
> xtrabackup/trunk/revision/218
>
> So to me it looks more like an extension to the documented behavior
> rather than a change in the workflow.

Alexey Kopytov (akopytov) wrote :

Kenny,

Thanks for the pointers. I assume you were referring to the output of
'innobackupex-1.5.1 --help'. OK, so it was documented, but did not
actually work.

But my point remains: there are no changes in the documented behavior.
It was rather an incomplete documentation on the wiki, and a help text
in innobackupex describing a buggy feature.

On 13.02.11 14:26, Kenny Gryp wrote:
> On 13 Feb 2011, at 11:01, Alexey Kopytov wrote:
>
>> Is there really a change in the workflow after the fix for this bug?
>> http://www.percona.com/docs/wiki/percona-
>> xtrabackup:xtrabackup:incremental does not mention using innobackupex
>> for incremental backups at all. So the only documented way is to use
>> xtrabackup.
>
>
> Alexey, FYI:
>
> the innobackupex-1.5.1 documentation mentioned it was possible:
> --redo-only Options is used with --apply-log. This option forces to skip
> "rollback" phase and do only "redo". This is necessary to use
> if backup later will be applied with incremental changes.
>
> And changelog of 1.4 mentioned that it was possible:
> Incremental backups have changed and now allow the restoration of full backups containing certain rollback transactions that previously caused problems. Please see Preparing the Backupsand the --apply-log-only option. (From innobackupex, the --redo-only option should be used). (Yasufumi Kinoshita) (http://www.mysqlperformanceblog.com/2010/11/22/percona-xtrabackup-1-4/)
>
>
>>
>> What's different now is that:
>>
>> 1. innobackupex *may* be used now instead of xtrabackup to prepare the
>> full backup.
>>
>> 2. innobackupex *may* be used now instead of xtrabackup to apply the
>> incremental backup. This change is a result of the fixes for this bug
>> and http://bazaar.launchpad.net/~percona-dev/percona-
>> xtrabackup/trunk/revision/218
>>
>> So to me it looks more like an extension to the documented behavior
>> rather than a change in the workflow.
>

Changed in percona-xtrabackup:
assignee: Vadim Tkachenko (vadim-tk) → Valentine Gostev (core-longbow)
Vadim Tkachenko (vadim-tk) wrote :

Assigned to Baron to document new options for innobackupex

Changed in percona-xtrabackup:
assignee: Valentine Gostev (core-longbow) → Xaprb (baron-xaprb)
Changed in percona-xtrabackup:
assignee: Xaprb (baron-xaprb) → Fred Linhoss (fred-linhoss)
Baron Schwartz (baron-xaprb) wrote :

There is no documentation now for innobackupex command line options, other than the tool's --help output. I would suggest that we close this bug after ensuring that --help is accurate with respect to the specific scope of the bug, and open a different one called "document innobackupex" if that is what we decide to do.

Changed in percona-xtrabackup:
milestone: 1.6 → 1.7
Stewart Smith (stewart) wrote :

Vadim, So it seems this bug is fixed? Please confirm so that we can close.

I have opened https://bugs.launchpad.net/percona-xtrabackup/+bug/785807 for documentation.

Changed in percona-xtrabackup:
assignee: Fred Linhoss (fred-linhoss) → Vadim Tkachenko (vadim-tk)
Vadim Tkachenko (vadim-tk) wrote :

I think it is fixed,
but I would ask Valentine to check it.

Stewart Smith (stewart) on 2011-05-20
Changed in percona-xtrabackup:
assignee: Vadim Tkachenko (vadim-tk) → Valentine Gostev (longbow)
Stewart Smith (stewart) on 2011-09-20
Changed in percona-xtrabackup:
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers