Assertion failure on apply-logs
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona XtraBackup moved to https://jira.percona.com/projects/PXB |
New
|
Undecided
|
Unassigned |
Bug Description
We're running xtrabackup 1.4-193.lucid.25 and percona server 5.1.54-
We're getting an intermittent assertion failure on apply-logs. Most days this works perfectly, but 1-2 times per week, the resulting backup fails to restore as described below.
Backups are created like this:
# /usr/bin/
The backup script that does this checks that the output said "completed OK!" at the end, and we're not getting any failures there.
To restore we first extract the tar archive into a new empty directory:
# cd /data/db
# tar xzvfi /var/backups/
Then apply-logs like this:
# innobackupex-1.5.1 --apply-log --use-memory=5G --ibbackup=
Version string '' contains invalid data; ignoring: '' at /usr/bin/
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!".
110222 11:52:01 innobackupex-1.5.1: Starting ibbackup with command: /usr/bin/xtrabackup --prepare --target-
/usr/bin/xtrabackup Ver 1.4 Rev 193 for 5.1.47 unknown-linux-gnu (x86_64)
xtrabackup: cd to /data/db
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=13926400, start_lsn=
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 5368709120 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_
110222 11:52:02 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 679026977997
110222 11:52:02 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 679032220672 (42 %)
InnoDB: Doing recovery: scanned up to log sequence number 679037463552 (84 %)
InnoDB: Doing recovery: scanned up to log sequence number 679039346585 (99 %)
110222 11:52:05 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 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 31396311, file name mysql-bin.000163
InnoDB: and relay log file
InnoDB: position 0 31396456, file name ./mysqld-
InnoDB: Last MySQL binlog file position 0 16782487, file name /var/log/
110222 11:52:30 Percona XtraDB (http://
110222 11:52:32 InnoDB: Assertion failure in thread 140009625151232 in file xtrabackup.c line 1141
InnoDB: Failing assertion: cset == 0
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-1.5.1: Error:
innobackupex-1.5.1: ibbackup failed at /usr/bin/
So, we currently don't have confidence in our backups. Any idea of the cause of this and how we might fix it?
Related branches
- Percona developers: Pending requested
- Diff: 0 lines
- Alexey Kopytov (community): Approve
-
Diff: 92 lines (+47/-4)3 files modifiedtest/t/bug723097.sh (+38/-0)
test/t/bug723097.sql (+5/-0)
utils/build.sh (+4/-4)
I found a clue. Trying to start mysql after the failed restore flagged a problem with the ib_logfile* sizes. After the (failed) restore, there are no ib_logfile* files in the data dir. Logfile size on both backup and restore machines is set to 64M. Starting mysql at this point results in a single 14M log file being created, leading to this error in the logs:
110222 14:17:12 [Note] Plugin 'FEDERATED' is disabled. rel12.5- log' socket: '/var/run/ mysqld/ mysqld. sock' port: 3306 (Percona Server (GPL), 12.5 , Revision 188)
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
110222 14:17:12 InnoDB: Initializing buffer pool, size = 5.4G
110222 14:17:12 InnoDB: Completed initialization of buffer pool
InnoDB: Error: log file ./ib_logfile0 is of different size 0 13926400 bytes
InnoDB: than specified in the .cnf file 0 67108864 bytes!
110222 14:17:12 [ERROR] Plugin 'InnoDB' init function returned error.
110222 14:17:12 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
110222 14:17:13 [Note] Event Scheduler: Loaded 0 events
110222 14:17:13 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.54-
Is it correct that xtrabackup does not include the ib_logfile* files?