Server reports InnoDB: Error: page <nr> log sequence number <nr> InnoDB: is in the future! Current system log sequence number <nr>. on first start after archive logs applied.
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona XtraBackup moved to https://jira.percona.com/projects/PXB |
Incomplete
|
Undecided
|
Unassigned | ||
2.1 |
Incomplete
|
Undecided
|
Unassigned |
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.
- Copy all full ib_log_archive files to $PWD/backup-0.1
- Stop load and server.
- Prepare backup with command: xtrabackup --defaults-
- Delete server data dir, recreate and run: innobackupex --defaults-
- Start server...
2013-06-27 16:29:43 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_
2013-06-27 16:29:43 22085 [Warning] You need to use --log-bin to make --binlog-format work.
2013-06-27 16:29:43 22085 [Note] Plugin 'FEDERATED' is disabled.
2013-06-27 16:29:43 22085 [Note] InnoDB: The InnoDB memory heap is disabled
2013-06-27 16:29:43 22085 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-06-27 16:29:43 22085 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-06-27 16:29:43 22085 [Note] InnoDB: Using Linux native AIO
2013-06-27 16:29:43 22085 [Note] InnoDB: Not using CPU crc32 instructions
2013-06-27 16:29:43 22085 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2013-06-27 16:29:43 22085 [Note] InnoDB: Completed initialization of buffer pool
2013-06-27 16:29:43 22085 [Note] InnoDB: Highest supported file format is Barracuda.
2013-06-27 16:29:43 22085 [Warning] InnoDB: The log sequence number in the ibdata files is higher than the log sequence number in the ib_logfiles! Are you sure you are using the right ib_logfiles to start up the database. Log sequence number in the ib_logfiles i
s 44864012, logsequence numbers stamped to ibdata file headers are between 94325231 and 94325231.
2013-06-27 16:29:43 22085 [Note] InnoDB: The log sequence numbers 94325231 and 94325231 in ibdata files do not match the log sequence number 44864012 in the ib_logfiles!
2013-06-27 16:29:43 22085 [Note] InnoDB: Database was not shutdown normally!
2013-06-27 16:29:43 22085 [Note] InnoDB: Starting crash recovery.
2013-06-27 16:29:43 22085 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-06-27 16:29:43 22085 [Note] InnoDB: Restoring possible half-written data pages
2013-06-27 16:29:43 22085 [Note] InnoDB: from the doublewrite buffer...
2013-06-27 16:29:43 7fc3e49c0720 InnoDB: Error: page 7 log sequence number 66252945
InnoDB: is in the future! Current system log sequence number 44864012.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://
InnoDB: for more information.
2013-06-27 16:29:43 7fc3e49c0720 InnoDB: Error: page 1 log sequence number 48683291
InnoDB: is in the future! Current system log sequence number 44864012.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://
InnoDB: for more information.
2013-06-27 16:29:43 7fc3e49c0720 InnoDB: Error: page 3 log sequence number 48683291
InnoDB: is in the future! Current system log sequence number 44864012.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://
InnoDB: for more information.
...this goes on for several hundred times
When the server is ready, all expected data seems there and server _seems_ OK, but these kinds of errors coming off what s supposed to be a fresh restore are concerning.
tags: | added: log-archiving |
More info:
When trying something out for Vlad, I noticed that I am getting these errors on the first restore in my test cycle. This means that there were no archive logs involved. I tried the following test without innodb_log_archive enabled:
innobackupex --defaults- file=$PWD/ mysql.1/ my.cnf --no-timestamp --tmpdir=$PWD $PWD/backup-0.0 file=$PWD/ mysql.1/ my.cnf --prepare --target- dir=$PWD/ backup- 0.0 file=$PWD/ mysql.1/ my.cnf --copy-back $PWD/backup-0.0 defaults_ for_timestamp server option (see documentation for more details). dev.mysql. com/doc/ refman/ 5.6/en/ forcing- innodb- recovery. html dev.mysql. com/doc/ refman/ 5.6/en/ forcing- innodb- recovery. html
xtrabackup --defaults-
InnoDB: Shutdown completed; log sequence number 82159141
rm -rf $PWD/mysql.1/data; mkdir $PWD/mysql.1/data
innobackupex --defaults-
start server:
2013-07-01 16:46:28 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_
2013-07-01 16:46:28 13627 [Warning] You need to use --log-bin to make --binlog-format work.
2013-07-01 16:46:28 13627 [Note] Plugin 'FEDERATED' is disabled.
2013-07-01 16:46:28 13627 [Note] InnoDB: The InnoDB memory heap is disabled
2013-07-01 16:46:28 13627 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-07-01 16:46:28 13627 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-07-01 16:46:28 13627 [Note] InnoDB: Using Linux native AIO
2013-07-01 16:46:28 13627 [Note] InnoDB: Not using CPU crc32 instructions
2013-07-01 16:46:28 13627 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2013-07-01 16:46:28 13627 [Note] InnoDB: Completed initialization of buffer pool
2013-07-01 16:46:28 13627 [Note] InnoDB: Setting log file ./ib_logfile101 size to 256 MB
InnoDB: Progress in MB: 100 200
2013-07-01 16:46:28 13627 [Note] InnoDB: Setting log file ./ib_logfile1 size to 256 MB
InnoDB: Progress in MB: 100 200
2013-07-01 16:46:29 13627 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2013-07-01 16:46:29 13627 [Warning] InnoDB: New log files created, LSN=82159141
2013-07-01 16:46:29 13627 [Note] InnoDB: Highest supported file format is Barracuda.
2013-07-01 16:46:29 7f22d9d28720 InnoDB: Error: page 195 log sequence number 82159641
InnoDB: is in the future! Current system log sequence number 82159628.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://
InnoDB: for more information.
2013-07-01 16:46:29 7f22d9d28720 InnoDB: Error: page 466 log sequence number 82159641
InnoDB: is in the future! Current system log sequence number 82159628.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://
InnoDB: for more information.
... on and on ...