Archive log prepare reports 'InnoDB: Archive log file <nr> does not scan right' when using --to-archived-lsn
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona XtraBackup moved to https://jira.percona.com/projects/PXB |
Fix Released
|
High
|
Vlad Lesin | ||
2.1 |
Fix Released
|
High
|
Vlad Lesin | ||
2.2 |
Fix Released
|
High
|
Vlad Lesin |
Bug Description
Using PS 5.6 trunk (revno 389) and ~vlad-lesin/
Sequence is pretty simple:
- Start server with: --binlog-format=ROW --innodb_
- Start sysbench 100% write load, 2 threads, 16 tables and 10000 max rows per table
- Wait 5 seconds
- Take base backup with command: innobackupex --defaults-
- Wait 10-20 seconds, enough time to get 15 or 20 ib_log_archive files.
- Capture current server lsn through "SHOW ENGINE INNODB STATUS", in this case it is 96004922
- Wait for a new ib_log_archive file to appear with starting lsn greater than captured lsn
- Copy all full ib_log_archive with starting lsn less than captured lsn to $PWD/backup-0.1
- Stop load and server.
- Prepare backup with command: xtrabackup --defaults-
xtrabackup version 2.1.3 for MySQL server 5.6.10 Linux (x86_64) (revision id: undefined)
xtrabackup: cd to /mnt/test/
xtrabackup: Temporary instance for recovery is set as followings.
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
xtrabackup: innodb_
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 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: CPU does not support crc32 instructions
InnoDB: Initializing buffer pool, size = 100.0M
InnoDB: Completed initialization of buffer pool
InnoDB: Setting log file ./ib_logfile101 size to 2 MB
InnoDB: Setting log file ./ib_logfile1 size to 2 MB
InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
InnoDB: New log files created, LSN=45138444
InnoDB: Starting archive recovery from a backup...
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
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: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Opened archived log file /mnt/test/
InnoDB: Archive log file /mnt/test/
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: 2 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 37120
[notice (again)]
If you use binary log and don't use any hack of group commit,
the binary log position seems to be:
xtrabackup: starting shutdown with innodb_
InnoDB: Starting shutdown...
InnoDB: Log sequence number at shutdown 45138956 is lower than at startup 96005102!
InnoDB: Shutdown completed; log sequence number 45138956
The test validates fine and everything seems ok, but that could be a concerning note to a user.
Related branches
- Alexey Kopytov (community): Approve
- Laurynas Biveinis (community): Needs Fixing
-
Diff: 1525 lines (+1383/-17)3 files modifiedpatches/innodb56.patch (+822/-0)
src/xtrabackup.cc (+172/-17)
test/t/xb_apply_archived_logs.sh (+389/-0)
tags: | added: log-archiving |
Fixed in the last version of related branch. George, could you check it please?