XtraBackup incremental backup crashes Percona mysql

[DVSoftware]

Hi, we are in a process of finding a good solutions for hourly incremental backups, and many people recommended XtraBackup.
We are currently making extensive testing and we have a really strange problem. When we restore a backup created with XtraBackup (2.0.0), our MySQL server (Percona 5.5.21-55) works for a while and then crashes miserably, and cannot be started again.
With the copy of /var/lib/mysql before restoring XtraBackup backup, everything works fine.
Here is an outline of the whole process:

Creating the base backup:
  innobackupex /home/backups/xtrabackup

Creating a few incremental backups:
  innobackupex --incremental /home/backups/xtrabackup --incremental-basedir=/home/backups/xtrabackup/2012-04-11_11-32-50
  innobackupex --incremental /home/backups/xtrabackup --incremental-basedir=/home/backups/xtrabackup/2012-04-11_11-34-08
  innobackupex --incremental /home/backups/xtrabackup --incremental-basedir=/home/backups/xtrabackup/2012-04-11_11-34-44

Copying base to another folder (i want to keep untouched base)
  cp -r /home/backups/xtrabackup/2012-04-11_11-32-50 restore

Preparing
  innobackupex --apply-log --redo-only /home/backups/xtrabackup/restore
  innobackupex --apply-log /home/backups/xtrabackup/restore --incremental-dir=/home/backups/xtrabackup/2012-04-11_11-34-08
  innobackupex --apply-log /home/backups/xtrabackup/restore --incremental-dir=/home/backups/xtrabackup/2012-04-11_11-34-44
  innobackupex --apply-log /home/backups/xtrabackup/restore --incremental-dir=/home/backups/xtrabackup/2012-04-11_11-35-22
  innobackupex --apply-log /home/backups/xtrabackup/restore

Stopped the mysql and restored using
  innobackupex --copy-back restore

Fixed the permissions and started mysql
  chown -R mysql:mysql /var/lib/mysql

And here is an error log from mysql (Just to remind, it doesn't happen immediately, but after a while):
Version: '5.5.21-55-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release 25.1
InnoDB: Error: trying to access page number 4294966143 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
120411 12:02:24 InnoDB: Assertion failure in thread 140707002947328 in file fil0fil.c line 5268
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.
10:02:24 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. 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.

key_buffer_size=536870912
read_buffer_size=33554432
max_used_connections=7
max_threads=151
thread_count=3
connection_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5783352 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7461410
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 = 7ff8e6ed8e88 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x7c19e5]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x691454]
/lib/libpthread.so.0(+0xeff0)[0x7ff8e6abbff0]
/lib/libc.so.6(gsignal+0x35)[0x7ff8e5cb71b5]
/lib/libc.so.6(abort+0x180)[0x7ff8e5cb9fc0]
/usr/sbin/mysqld[0x8ec1e1]
/usr/sbin/mysqld[0x8c676b]
/usr/sbin/mysqld[0x8c6eb0]
/usr/sbin/mysqld[0x8b8efb]
/usr/sbin/mysqld[0x902536]
/usr/sbin/mysqld[0x8746f2]
/usr/sbin/mysqld[0x88c323]
/usr/sbin/mysqld[0x888431]
/usr/sbin/mysqld[0x888965]
/usr/sbin/mysqld[0x889b6b]
/usr/sbin/mysqld[0x832323]
/usr/sbin/mysqld[0x83827d]
/usr/sbin/mysqld(_Z19ha_commit_one_phaseP3THDb+0x7f)[0x696c5f]
/usr/sbin/mysqld(_Z15ha_commit_transP3THDb+0x1fe)[0x696f2e]
/usr/sbin/mysqld(_Z17trans_commit_stmtP3THD+0x1d)[0x64178d]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x4c4)[0x593ca4]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x333)[0x598323]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x15b2)[0x599982]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0xdf)[0x633b6f]
/usr/sbin/mysqld(handle_one_connection+0x51)[0x633ca1]
/lib/libpthread.so.0(+0x68ca)[0x7ff8e6ab38ca]
/lib/libc.so.6(clone+0x6d)[0x7ff8e5d5486d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7481740): UPDATE pun_users SET `last_active`=1334138544 WHERE `id`='2'
Connection ID (thread ID): 649
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
120411 12:02:24 mysqld_safe Number of processes running now: 0
120411 12:02:24 mysqld_safe mysqld restarted
120411 12:02:24 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in a future release. Please use '--slow-query-log'/'--slow-query-log-file' instead.
120411 12:02:24 [Warning] The syntax '--log' is deprecated and will be removed in a future release. Please use '--general-log'/'--general-log-file' instead.
120411 12:02:24 [Note] Flashcache bypass: disabled
120411 12:02:24 [Note] Flashcache setup error is : ioctl failed

120411 12:02:24 [Note] Plugin 'FEDERATED' is disabled.
120411 12:02:24 InnoDB: The InnoDB memory heap is disabled
120411 12:02:24 InnoDB: Mutexes and rw_locks use GCC atomic builtins
120411 12:02:24 InnoDB: Compressed tables use zlib 1.2.3
120411 12:02:24 InnoDB: Using Linux native AIO
120411 12:02:24 InnoDB: Initializing buffer pool, size = 2.0G
120411 12:02:24 InnoDB: Completed initialization of buffer pool
120411 12:02:24 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 72101006
120411 12:02:24 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...
InnoDB: Doing recovery: scanned up to log sequence number 72101941
InnoDB: Error: trying to access page number 4294966143 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
120411 12:02:25 InnoDB: Assertion failure in thread 140568369575680 in file fil0fil.c line 5268
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.
10:02:25 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. 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.

key_buffer_size=536870912
read_buffer_size=33554432
max_used_connections=0
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5783352 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x7c19e5]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x691454]
/lib/libpthread.so.0(+0xeff0)[0x7fd89f7a3ff0]
/lib/libc.so.6(gsignal+0x35)[0x7fd89e99f1b5]
/lib/libc.so.6(abort+0x180)[0x7fd89e9a1fc0]
/usr/sbin/mysqld[0x8ec1e1]
/usr/sbin/mysqld[0x8c676b]
/usr/sbin/mysqld[0x8c6eb0]
/usr/sbin/mysqld[0x8b8efb]
/usr/sbin/mysqld[0x8803c5]
/usr/sbin/mysqld[0x88093d]
/usr/sbin/mysqld[0x88421a]
/usr/sbin/mysqld[0x86dd26]
/usr/sbin/mysqld[0x82f9e9]
/usr/sbin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x48)[0x6938d8]
/usr/sbin/mysqld[0x59ed5a]
/usr/sbin/mysqld(_Z11plugin_initPiPPci+0xa1d)[0x5a329d]
/usr/sbin/mysqld[0x51fb4a]
/usr/sbin/mysqld(_Z11mysqld_mainiPPc+0x5cd)[0x5235cd]
/lib/libc.so.6(__libc_start_main+0xfd)[0x7fd89e98bc8d]
/usr/sbin/mysqld[0x519179]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
120411 12:02:25 mysqld_safe mysqld from pid file /var/lib/mysql/Debian-60-squeeze-64-LAMP.pid ended

[Valentine Gostev (longbow)]

Hello,

most likely mysqld crashed since data was damaged while incorrectly preparing the backup:
when you were preparing a full backup you used --redo-only option, this option is also needed when you apply incrementals, should be like:

innobackupex --apply-log --redo-only /home/backups/xtrabackup/restore
innobackupex --apply-log --redo-only /.../restore --incremental-dir=/.../inc1
innobackupex --apply-log --redo-only /.../restore --incremental-dir=/.../inc2
....
innobackupex --apply-log /home/backups/xtrabackup/restore

So if you are going to apply several incremental changes - this also should be done with --redo-only option.

Please try this and let us know if it helps. For now I will mark bug as incompleted.
Thank you.

[DVSoftware (dvsoftware)]

Hi,
Thanks for suggestion, so far the DB is stable.
You'll want to update the docs (http://www.percona.com/doc/percona-xtrabackup/howtos/recipes_ibkx_inc.html) as it's not mentioned in there.

[Shahriyar Rzayev (rzayev-sehriyar)]

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