Restore of differential fails during apply log with 'xtrabackup got signal 11'

Bug #1455810 reported by vincent.seguin
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup moved to https://jira.percona.com/projects/PXB
Expired
Undecided
Unassigned

Bug Description

This occurs with xtrabackup 2.2.6 and 2.2.10.
When trying to restore a large differential backup, innobackupex fails during the differential apply-log phase with:
(This is the 2.2.10 log, but 2.2.6 is equivalent - specific file names have been blanked out for confidentiality):

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
[...]
150515 21:08:47 innobackupex: Starting the apply-log operation
[...]
150515 21:08:47 innobackupex: Starting ibbackup with command: xtrabackup --defaults-file="*****" --defaults-group="mysqld" --prepare --target-dir=****** --use-memory=32G --incremental-dir=*******

xtrabackup version 2.2.10 based on MySQL server 5.6.22 Linux (x86_64) (revision id: )
incremental backup from 48483536728613 is enabled.
xtrabackup: cd to **************
xtrabackup: This target seems to be already prepared with --apply-log-only.

[......]

InnoDB: Doing recovery: scanned up to log sequence number 48564861605888 (78%)
InnoDB: Doing recovery: scanned up to log sequence number 48564866848768 (78%)
InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 04:24:16 UTC - xtrabackup got signal 11 ;
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: 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 0x10000
xtrabackup(my_print_stacktrace+0x35) [0x9f5331]
xtrabackup(handle_fatal_signal+0x2bb) [0x7f801b]
/lib64/libpthread.so.0(+0xf710) [0x7f68f003e710]
xtrabackup() [0x6eb42b]
xtrabackup() [0x6ebf70]
xtrabackup() [0x6ec33b]
xtrabackup() [0x6ed358]
xtrabackup(page_cur_insert_rec_low(unsigned char*, dict_index_t*, unsigned char const*, unsigned long*, mtr_t*)+0x4fc) [0x6ef32a]
xtrabackup() [0x6ed882]
xtrabackup(page_cur_parse_insert_rec(unsigned long, unsigned char*, unsigned char*, buf_block_t*, dict_index_t*, mtr_t*)+0x634) [0x6eed97]
xtrabackup() [0x75000d]
xtrabackup(recv_recover_page_func(unsigned long, buf_block_t*)+0x3c5) [0x751231]
xtrabackup(buf_page_io_complete(buf_page_t*)+0x449) [0x6a4dd9]
xtrabackup(fil_aio_wait(unsigned long)+0x14d) [0x68b480]
xtrabackup(io_handler_thread+0x25) [0x725ee6]
/lib64/libpthread.so.0(+0x79d1) [0x7f68f00369d1]
/lib64/libc.so.6(clone+0x6d) [0x7f68ee7108fd]

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Hi,

As per the above log, I can see this msg

xtrabackup: This target seems to be already prepared with --apply-log-only.

Are you going to prepare the backup which is already prepared? Can you provide the exact commands for how you are taking backup and apply log? Also what do you mean by "large differential backup" ?

Changed in percona-xtrabackup:
status: New → Incomplete
Revision history for this message
vincent.seguin (vincent-seguin) wrote :

Taking the backups (those commands stream to a remote location):

Full:
innobackupex --defaults-file=XXX --compress --user=XXX --throttle=50000 --parallel=1 --stream=xbstream --tmpdir=XXX --no-lock work_dir

Differential:
innobackupex --defaults-file=XXX --incremental --incremental_lsn=XXXX --compress --user=XXX --throttle=50000 --parallel=1 --stream=xbstream --tmpdir=XXX --no-lock work_dir

The defaults file is our regular my.cnf file plus backup user credentials.

Starting with expanded decompressed backups in work_dir (full) and differential_dir:

innobackupex --apply-log --redo-only --use-memory=32G work_dir 2> full.log
innobackupex --apply-log --incremental-dir incremental_dir --use-memory=32G work_dir 2> differential.log

The first command works fine, the second one is the one raising signal 11.

Full backup size is 1.36T (compressed, so ~2.2T after expansion).
Differential is 76G compressed.

Also, we do hundreds of restores a week of various databases using that exact process. We encountered that issue twice on two distinct differentials of the same source DB (and sharing the same from_lsn/full).

Changed in percona-xtrabackup:
status: Incomplete → New
Revision history for this message
Sveta Smirnova (svetasmirnova) wrote :

Which filesystem for backup and datadir do you use?

Changed in percona-xtrabackup:
status: New → Incomplete
Revision history for this message
vincent.seguin (vincent-seguin) wrote :

@Sveta
Data directory is on XFS
Backup arrives as a xbstream, expands to XFS and restores from there

Changed in percona-xtrabackup:
status: Incomplete → New
Revision history for this message
Sveta Smirnova (svetasmirnova) wrote :

Thank you for the feedback.

I see you use this sequence of actions:

innobackupex --apply-log --redo-only --use-memory=32G work_dir 2> full.log
innobackupex --apply-log --incremental-dir incremental_dir --use-memory=32G work_dir 2> differential.log

However you skipped --redo-only for the incremental backup. Can you repeat the issue if run:

innobackupex --apply-log --redo-only --use-memory=32G work_dir 2> full.log
innobackupex --apply-log --redo-only --incremental-dir incremental_dir --use-memory=32G work_dir 2> differential.log

Changed in percona-xtrabackup:
status: New → Incomplete
Revision history for this message
vincent.seguin (vincent-seguin) wrote :

> However you skipped --redo-only for the incremental backup.

Indeed.
This is embarrassing.

I'll try the proper sequence and verify that the issue no longer occur. (That might take a while).

Thanks

Revision history for this message
vincent.seguin (vincent-seguin) wrote :

So, documentation says: (https://www.percona.com/doc/percona-xtrabackup/2.4/innobackupex/incremental_backups_innobackupex.html)

"--redo-only should be used when merging all incrementals except the last one."

So I think my sequence is correct. Or is it?
I'll see if I can find a broken restore to try the additional --redo-only on just in case.

Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for Percona XtraBackup because there has been no activity for 60 days.]

Changed in percona-xtrabackup:
status: Incomplete → Expired
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-1327

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

Other bug subscribers

Remote bug watches

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