percona-discussion team mailing list archive

[Percona <launchpad@xxxxxxxxxxx>]

Public bug reported:

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.

** Affects: percona-xtrabackup
     Importance: Undecided
         Status: New

-- 
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.