percona-discussion team mailing list archive

Thread
Date
[Bug 352742] Re: Problem during --apply-log

To: percona-discussion@xxxxxxxxxxxxxxxxxxx
From: Percona <launchpad@xxxxxxxxxxx>
Date: Thu, 02 Apr 2009 20:27:41 -0000
Reply-to: Bug 352742 <352742@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
After fix it works better, but I still see unclear messages:

InnoDB: Doing recovery: scanned up to log sequence number 1318 1142470656 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1147713536 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1152956416 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1158199296 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1163442176 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1168685056 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 1318 1172160781 (99 %)
InnoDB: ##########################################################
InnoDB:                          WARNING!
InnoDB: The log sequence number in ibdata files is higher
InnoDB: than the log sequence number in the ib_logfiles! Are you sure
InnoDB: you are using the right ib_logfiles to start up the database?
InnoDB: Log sequence number in ib_logfiles is 1317 3806902419, log
InnoDB: sequence numbers stamped to ibdata file headers are between
InnoDB: 1318 1213947916 and 1318 1213947916.
InnoDB: ##########################################################
090402 13:30:43  InnoDB: ERROR: We were only able to scan the log up to 1318 1172160781
InnoDB: but a database page a had an lsn 1318 1213947739. It is possible that the
InnoDB: database is now corrupt!
090402 13:30:43  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: Last MySQL binlog file position 0 165363629, file name ./db02-bin.001266
090402 14:09:59  InnoDB: Started; log sequence number 1318 1172160781
InnoDB: Last MySQL binlog file position 0 165363629, file name ./db02-bin.001266
090402 14:09:59  InnoDB: Starting shutdown...
090402 14:10:01  InnoDB: Shutdown completed; log sequence number 1318 1172160781
xtrabackup  Ver beta-0.4 for 5.0.77 unknown-linux-gnu (x86_64)
xtrabackup_logfile detected: size=1660239872, start_lsn=(1317 3806902419)

-- 
Problem during --apply-log
https://bugs.launchpad.net/bugs/352742
You received this bug notification because you are a member of Percona
developers, which is the registrant for Percona-XtraBackup.

Status in Open source backup tool for InnoDB and XtraDB: New

Bug description:
backup was finished with next information:

>> log scanned up to (1317 3505471428)
Transaction log of lsn (1317 1513697222) to (1317 3505471428) was copied.
090331 16:30:11  innobackupex: All tables unlocked
090331 16:30:11  innobackupex: Connection to database server closed

innobackupex: Backup created in directory '/mnt/data/tmp'
innobackupex: MySQL binlog position: filename 'db02-bin.001263', position 1031512296    
090331 16:34:21  innobackupex: innobackup completed OK!
innobackupex: You must use -i (--ignore-zeros) option for extraction of the tar stream.

Now I run --apply-log:

innobackupex-1.5.1 --use-memory=1G --apply-log /mnt/data/db 

and after some period of time getting error:

InnoDB: Doing recovery: scanned up to log sequence number 1317 2043227648 (26 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2048470528 (26 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2053713408 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2058956288 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2064199168 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 1317 2067140096 (27 %)
090331 17:54:23  InnoDB: ERROR: We were only able to scan the log up to 1317 2067140096
InnoDB: but a database page a had an lsn 1317 3480803499. It is possible that the
InnoDB: database is now corrupt!
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 4 row operations to undo
InnoDB: Trx id counter is 4 86778112
090331 17:54:23  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: Last MySQL binlog file position 0 3570942, file name ./db02-bin.001262
InnoDB: Starting in background the rollback of uncommitted transactions
090331 18:11:09  InnoDB: Rolling back trx with id 4 86777617, 4 rows to undo
090331 18:11:09  InnoDB: Started; log sequence number 1317 2067140018

[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 3570942, file name ./db02-bin.001262

090331 18:11:09  InnoDB: Starting shutdown...
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933cd5; asc I < ;; 1: len 8; hex 000000007917bd3d; asc     y  =;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933b07; asc I ; ;; 1: len 8; hex 000000007916f43d; asc     y  =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK , undo log entries 3

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933ebd; asc I > ;; 1: len 8; hex 000000007918193d; asc     y  =;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933d6e; asc I =n;; 1: len 8; hex 000000007916f03d; asc     y  =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK , undo log entries 2

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933bf0; asc I ; ;; 1: len 8; hex 000000007918353d; asc     y 5=;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933b07; asc I ; ;; 1: len 8; hex 000000007916f43d; asc     y  =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK , undo log entries 1

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: error in sec index entry del undo in
InnoDB: index "inserted" of table "art61/article61"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 49933f0b; asc I ? ;; 1: len 8; hex 0000000079182c3d; asc     y ,=;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 49933d6e; asc I =n;; 1: len 8; hex 000000007916f03d; asc     y  =;;

TRANSACTION 4 86777617, ACTIVE 1006 sec, process no 1316, OS thread id 1133762880
ROLLING BACK 

InnoDB: Submit a detailed bug report to http://bugs.mysql.com

InnoDB: Rolling back of trx id 4 86777617 completed
090331 18:11:09  InnoDB: Rollback of non-prepared transactions completed

and process seems hung there.
References

[Bug 352742] [NEW] Problem during --apply-log
From: Percona, 2009-03-31