xtrabackup Assertion failure with Apply log process
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
| Percona XtraBackup moved to https://jira.percona.com/projects/PXB |
Fix Released
|
Medium
|
Sergei Glushchenko | |
| 2.1 |
Triaged
|
Medium
|
Sergei Glushchenko | |
| 2.2 |
Fix Released
|
Medium
|
Sergei Glushchenko | |
| 2.3 |
Fix Released
|
Medium
|
Sergei Glushchenko |
Bug Description
While applying the log we are facing an assertion failure issue with xtrabackup version 2.1.9 so we decided to upgrade the tool to version 2.2.3. But still we are hitting the same error.
The issue is not occurring on every try, last time we found the issue when we initiated an incremental backup proceeding to a full backup. We have completed the full backup successfully but the incremental ended with the same error. Log details are given below.
Version :
[05:54:02 xxx@xxxx:~]# xtrabackup -v
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
[xxxx@xxxxxx~]$ innobackupex --version
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
mysql version: 5.6.17-66.0-log
Log:
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 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: In a MySQL replication slave the last master binlog file
InnoDB: position 0 329970412, file name data3-bin.001806
InnoDB: Last MySQL binlog file position 0 883545871, file name data1-bin.002972
InnoDB: 128 rollback segment(s) are active.
InnoDB: Waiting for purge to start
InnoDB: 5.6.17 started; log sequence number 13967966489023
[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 883545871, file name data1-bin.002972
xtrabackup: starting shutdown with innodb_
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
2014-09-12 05:13:40 4a7ee940 InnoDB: Assertion failure in thread 1249831232 in file buf0flu.cc line 2503
InnoDB: Failing assertion: UT_LIST_
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://
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://
InnoDB: about forcing recovery.
innobackupex: Error:
innobackupex: ibbackup failed at /usr/bin/
Related branches
Arunjith (arunjith-aravindan) wrote : | #2 |
Here is the recent log:
140916 05:43:38 innobackupex: Starting ibbackup with command: xtrabackup --defaults-
Warning: World-writable config file '/mnt/MOUNTED_
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
incremental backup from 14111243331989 is enabled.
xtrabackup: cd to /mnt/MOUNTED_
xtrabackup: This target seems to be already prepared.
xtrabackup: xtrabackup_logfile detected: size=1891237888, start_lsn=
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: page size for /mnt/MOUNTED_
InnoDB: Failed to set O_DIRECT on file /mnt/MOUNTED_
Applying /mnt/MOUNTED_
xtrabackup: page size for /mnt/MOUNTED_
Applying /mnt/MOUNTED_
xtrabackup: page size for /mnt/MOUNTED_
Applying /mnt/MOUNTED_
xtrabackup: page size for /mnt/MOUNTED_
Applying /mnt/MOUNTED_
xtrabackup: page size for /mnt/MOUNTED_
Applying /mnt/MOUNTED_
xtrabackup: page size fo...
Changed in percona-xtrabackup: | |
status: | Incomplete → New |
Jeff Jordan (jdjordan) wrote : | #3 |
I am getting an assertion failure when running innobackupex --apply-log as well.
Package: xtrabackup
Source: percona-xtrabackup
Version: 2.2.4-5004-1.wheezy
innobackupex --apply-log 2014-10-
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:
http://
IMPORTANT: Please check that the apply-log run completes successfully.
At the end of a successful apply-log run innobackupex
prints "completed OK!".
141001 17:00:33 innobackupex: Starting ibbackup with command: xtrabackup --defaults-
xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64) (revision id: )
xtrabackup: cd to /app/backup/
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
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: Compressed tables use zlib 1.2.3
InnoDB: 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 572982443902
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 572984104313 (89%)
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 12 13 14 15 16 17 18 19 20 21 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...
Nilnandan Joshi (nilnandan-joshi) wrote : | #4 |
Unable to reproduce the same with PS 5.6.17 and Xtrabackup 2.2.5
Can you please try to check the same with latest version of Xtrabackup? (2.2.5)
Also please provide the exact command of taking full backup, incremental backup and apply log. It might helpful to reproduce this bug.
Changed in percona-xtrabackup: | |
status: | New → Incomplete |
Arunjith (arunjith-aravindan) wrote : Re: [Bug 1368846] Re: xtrabackup Assertion failure with Apply log process | #5 |
Joshi,
I have upgraded the xtrabackup to version 2.2.5 and initiated the
incremental backup.
Currently the incremental backup has been completed successfully and the
apply-log process is in progress.
I will update you the details.
# /usr/bin/xtrabackup -v
/usr/bin/xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux
(x86_64) (revision id: )
On Sun, Oct 12, 2014 at 3:26 PM, Nilnandan Joshi <
<email address hidden>> wrote:
> Unable to reproduce the same with PS 5.6.17 and Xtrabackup 2.2.5
>
> Can you please try to check the same with latest version of Xtrabackup?
> (2.2.5)
>
> Also please provide the exact command of taking full backup, incremental
> backup and apply log. It might helpful to reproduce this bug.
>
> ** Changed in: percona-xtrabackup
> Status: New => Incomplete
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https:/
>
> Title:
> xtrabackup Assertion failure with Apply log process
>
> Status in Percona XtraBackup:
> Incomplete
>
> Bug description:
> While applying the log we are facing an assertion failure issue with
> xtrabackup version 2.1.9 so we decided to upgrade the tool to version
> 2.2.3. But still we are hitting the same error.
>
> The issue is not occurring on every try, last time we found the issue
> when we initiated an incremental backup proceeding to a full backup.
> We have completed the full backup successfully but the incremental
> ended with the same error. Log details are given below.
>
> Version :
> [05:54:02 xxx@xxxx:~]# xtrabackup -v
> xtrabackup version 2.2.3 based on MySQL server 5.6.17 Linux (x86_64)
> (revision id: )
>
> [xxxx@xxxxxx~]$ innobackupex --version
> InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
>
> mysql version: 5.6.17-66.0-log
>
> Log:
>
> InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17
> 18 19 20 21 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: In a MySQL replication slave the last master binlog file
> InnoDB: position 0 329970412, file name data3-bin.001806
> InnoDB: Last MySQL binlog file position 0 883545871, file name
> data1-bin.002972
> InnoDB: 128 rollback segment(s) are active.
> InnoDB: Waiting for purge to start
> InnoDB: 5.6.17 started; log sequence number 13967966489023
>
> [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 883545871, file name
> data1-bin.002972
>
> xtrabackup: starting shutdown with innodb_
> InnoDB: FTS optimize thread exiting.
> InnoDB: Starting shutdown...
> 2014-09-12 05:13:40 4a7ee940 InnoDB: Assertion failure in thread
> 1249831232 in file buf0flu.cc line 2503
> InnoDB: Failing assertion: UT_LIST_
> InnoDB: We intentionally generate a ...
Jeff Jordan (jdjordan) wrote : | #6 |
root@db075:
Desired=
| Status=
|/ Err?=(none)
||/ Name Version Architecture Description
+++-===
ii percona-xtrabackup 2.2.5-5027-1.wheezy amd64 Open source backup tool for InnoDB and XtraDB
root@db075:
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:
http://
141013 15:34:02 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:
141013 15:34:02 innobackupex: Connected to MySQL server
141013 15:34:02 innobackupex: Executing a version check against the server...
141013 15:34:02 innobackupex: Done.
IMPORTANT: Please check that the backup run completes successfully.
At the end of a successful backup run innobackupex
prints "completed OK!".
innobackupex: Using mysql server version 5.5.37-
innobackupex: Created backup directory /app/backup/
141013 15:34:02 innobackupex: Starting ibbackup with command: xtrabackup --defaults-
innobackupex: Waiting for ibbackup (pid=9358) to suspend
innobackupex: Suspend file '/app/backup/
xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /app/mysql/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
>> log scanned up to (4073210617)
[01] Copying ./ibdata1 to /app/backup/
[01] ...done
>> log scanned up to (4073211469)
[01] Copying ./comp1/
[01] ...done
[01] Copying ./comp1/
[01] ...done
[01] Copying ./comp1/
[01] ...done
[01] Copying ./comp1/
Arunjith (arunjith-aravindan) wrote : | #7 |
xtrabackup -v
xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64)
(revision id: )
Backup :
innobackupex: Created backup directory /mnt/RawPDFs-
data01.
141013 14:05:03 innobackupex: Starting ibbackup with command: xtrabackup
--defaults-
--target-
data01.
--extra-
--incremental-
data01.
innobackupex: Waiting for ibbackup (pid=13943) to suspend
innobackupex: Suspend file '/mnt/RawPDFs-
data01.
'
xtrabackup version 2.2.5 based on MySQL server 5.6.21 Linux (x86_64)
(revision id: )
incremental backup from 15331124206933 is enabled.
....
Apply log:
141013 16:41:09 innobackupex: Starting ibbackup with command: xtrabackup
--defaults-
data01.
--defaults-
--target-
data01.
--incremental-
data01.
Error details:
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://
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://
InnoDB: about forcing recovery.
00:15:33 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: 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(
xtrabackup(
/lib64/
/lib64/
/lib64/
xtrabackup(
xtrabackup(
long const*, mtr_t*)+0xc5) [0x738f49]
xtrabackup(
buf_block_t*, dict_index_t*, mtr_t*)+0x135) [0x7393eb]
xtrabackup [0x6d4439]
xtrabackup(
[0x6d5c6c]
xtrabackup(
xtrabackup(
xtrabackup(
...
Changed in percona-xtrabackup: | |
status: | Incomplete → New |
Alexey Kopytov (akopytov) wrote : | #8 |
The error log in comment #7 is truncated, so it is not clear whether it is the same assertion as in the original report, or a different one. From the stacktrace in comment #7 it looks like it was a different assertion. Can you confirm this?
Changed in percona-xtrabackup: | |
status: | New → Incomplete |
Arunjith (arunjith-aravindan) wrote : | #9 |
Please consider the delay in response as I was waiting for the backup to
complete. We are still hitting with the similar (Incremental Backup)
assertion failure and here is the recent error message from apply log
process.
Backup :
$INNOBACKUPEX_BIN --no-version-check --user=$USER --password=
--slave-info --incremental --incremental-
$BACKUP_
Apply log:
$INNOBACKUPEX_BIN --no-version-check --apply-log
--incremental-
-mindepth 1 -type d -name 20\* | sort | tail -n 1) >> $xb_prepare_log 2>&1
Log:
xtrabackup: starting shutdown with innodb_
InnoDB: FTS optimize thread exiting.
InnoDB: Starting shutdown...
2014-10-15 07:01:56 4b013940 InnoDB: Assertion failure in thread
1258371392 in file buf0flu.cc line 2507
InnoDB: Failing assertion: UT_LIST_
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://
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://
InnoDB: about forcing recovery.
12:01:56 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: 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(
xtrabackup(
/lib64/
/lib64/
/lib64/
xtrabackup(
/lib64/
/lib64/
On Tue, Oct 14, 2014 at 11:36 AM, Alexey Kopytov <<email address hidden>
> wrote:
> The error log in comment #7 is truncated, so it is not clear whether it
> is the same assertion as in the original report, or a different one.
> >From the stacktrace in comment #7 it looks like it was a different
> assertion. Can you confirm this?
>
> ** Changed in: percona-xtrabackup
> Status: New => Incomplete
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https:/
>
> Title:
> xtrabackup Assertion failure with Apply log process
>
> Status in Percona XtraBackup:
> Incomplete
>
> Bug description:
> While applying the log we are facing an assertion failure issue with
> xtrabackup version 2.1.9 so we decided to upgrade the tool to version
> 2.2.3. But still we are hitting the same error.
>
> The issue is not occurring on every try, last time we found the issu...
Alexey Kopytov (akopytov) wrote : | #10 |
OK, the assertion failure in comment #9 is identical to the one in the original report, but is different from the one in comment #7.
If you ever hit the assertion from comment #7 again, please file it as a separate bug.
Changed in percona-xtrabackup: | |
status: | Incomplete → Confirmed |
assignee: | nobody → Alexey Kopytov (akopytov) |
Alexey Kopytov (akopytov) wrote : | #11 |
Bug #1399873 was marked as a duplicate of this one.
Alok Pathak (alok-pathak) wrote : | #12 |
Hi,
We are hitting same bug with Percona Xtrabackup 2.2.7 version as well while preparing incremental backup. We are taking backup from slave server with binary logs enabled and backups are on stored on a cifs (windows) share.
# xtrabackup --version
xtrabackup version 2.2.7 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
# innobackupex --version
InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
mysql> show global variables like '%version%';
+------
| Variable_name | Value |
+------
| innodb_version | 5.6.21-70.1 |
| protocol_version | 10 |
| slave_type_
| version | 5.6.21-70.1-log |
| version_comment | Percona Server (GPL), Release 70.1, Revision 698 |
| version_
| version_compile_os | Linux |
+------
7 rows in set (0.01 sec)
mysql> show global variables like 'log_bin';
+------
| Variable_name | Value |
+------
| log_bin | ON |
+------
mysql> show global variables like '%log_slave%';
+------
| Variable_name | Value |
+------
| log_slave_updates | ON |
+------
1 row in set (0.00 sec)
# mount | grep -i cifs
//IP/Path on /mnt/Path type cifs (rw,mand)
Following are the commands used to take backup.
Taking full backup
# innobackupex --no-version-check --user=$USER --password=
-- Completed OK
Preparing full backup
# innobackupex --no-version-check --apply-log --redo-only --tmpdir=
-- Completed OK
Taking incremental backup
# innobackupex --no-version-check --user=$USER --password=
-- Completed OK
Preparing incremental backup
# innobackupex --no-version-check --apply-log --tmpdir=
InnoDB: Doing recovery: scanned up to log sequence number 19059978766316 (100%)
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 36794...
Interesting part from stack trace at the moment of crash:
Thread 8 (Thread 0x41e02940 (LWP 3699)):
#0 0x00000036aac0e438 in pread64 () from /lib64/
#1 0x0000000000636f15 in os_file_io(int, void*, unsigned long, long, unsigned long) ()
#2 0x00000000006373cc in os_file_pread(int, void*, unsigned long, unsigned long) ()
#3 0x0000000000637570 in os_file_
#4 0x0000000000638000 in os_aio_
#5 0x00000000006e4ae9 in fil_io(unsigned long, bool, unsigned long, unsigned long, unsigned long, unsigned long, unsigned long, void*, void*) ()
#6 0x00000000007699bd in buf_read_
#7 0x0000000000769d08 in buf_read_
#8 0x000000000065f722 in buf_page_
#9 0x00000000007791e5 in btr_block_get_func ()
#10 0x00000000007794b4 in btr_cur_
#11 0x0000000000781186 in btr_cur_
#12 0x0000000000714858 in btr_pcur_
#13 0x0000000000715960 in btr_pcur_
#14 0x000000000072ff5a in ibuf_restore_
#15 0x0000000000730558 in ibuf_delete_
#16 0x00000000007358f4 in ibuf_merge_
#17 0x00000000006618ed in buf_page_
#18 0x00000000006e2e14 in fil_aio_
#19 0x000000000079703a in io_handler_thread ()
#20 0x00000036aac0673d in start_thread () from /lib64/
#21 0x00000036aa0d44bd in clone () from /lib64/libc.so.6
Here we see that there is an ibuf merge is in progress caused by pending IO operation. I believe that page_cleaner thread should not exit until number of pending IOs comes down to zero.
Fix for originally reported assertion pushed to 2.2 branch https:/
Percona now uses JIRA for bug reports so this bug report is migrated to: https:/
I tried it with full + incremental scheme but was not able to reproduce it. Can you please show exact commands you used.