MySQL InnoDB Log – How to Resolve ‘In the Future’ Error

innodbMySQL

I've got this InnoDB error in MySQL 5.0. Mysqld was stopped cleanly, but I managed to lose ib_logfile0 & ib_logfile1 afterward. Now after a clean startup, InnoDB has done its "crash recovery". I went through the innodb_force_recovery=4 business, repaired a hung MyISAM table, and now replication is ready to go, apart from this. Big numbers commified:

111116 15:49:36  InnoDB: Error: page 393457 log sequence number 111 561,760,232
InnoDB: is in the future! Current system log sequence number 70 3,946,969,851.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: for more information.

This is on a slave server. The above error spews by the hundreds. I found this answer: "insert and delete > 64 GB worth of data, so that the log sequence number becomes inflated big enough".

http://forums.mysql.com/read.php?22,50163,50163#msg-50163

That magic number of 64GB comes from 4GB*16 where that guy's innodb log "major number" needed to increase from 0 to 15. Mine's going from 70 to 111 = 164 GB. This will take 5 days. I'll keep working on speeding up my script, and running it in parallel to speed this up. In the meantime, I'm hoping someone else has a better answer. This is silly.

Best Answer

This was a pretty rare situation. I hope to never end up there again, with an InnoDB "log sequence number is in the future!" error. Because of my particular details, rebuilding/restoring my server's data was a last resort. Some cheats in helping that were good ideas, but in the end, I decided to just keep improving my Perl script to play this silly game and churn through as many gigs/hour as I could. What the heck, it's a good system stress test.

Remember: the goal is to increase a single counter ("log sequence number") which is stored somewhere in the headers of ib_logfile0 and ib_logfile1. This is to fake out InnoDB so it will ignore an apparent time warp and get on with life. But no one knows how to edit that number. Or if they do know, no one's talking.

Here's my final product. YMMV, but using mysql's REPEAT function to generate the data internally is highly efficient.

 #!/usr/bin/perl
 use DBI;
 $table = shift || die;
 $dbh = DBI->connect("DBI:mysql:junk:host=localhost", "user", "pass"); #Edit "junk" (DB name), user, and pass to suit.
 $dbh->do("DROP TABLE IF EXISTS $table");
 $dbh->do("CREATE TABLE $table (str TEXT) ENGINE=INNODB");
 $sth = $dbh->prepare("INSERT INTO $table (str) VALUES (REPEAT(?,1000000))");
 foreach (1..50) {
    $sth->execute('0123456789');   # 10 MB
 }
 $dbh->do("DELETE FROM $table");

My suggested recipe:

Create a 'junk' database
Save the above perl script as junk.pl.
Run junk.pl data1, and junk.pl data2, and junk.pl data3, etc. all at once, for as many CPU cores as your database server has, to start. Open multiple shells and wrap each run in a Bash loop: while true; do date; junk.pl dataX; done.

Watch your LSN grow, perhaps in another loop:

 silly# echo "SHOW INNODB STATUS \G" | mysql -p'xxxxxx' | grep '^Log seq'
 Log sequence number 124 3871092821
 silly# echo "SHOW INNODB STATUS \G" | mysql -p'xxxxxx' | grep '^Log seq'
 Log sequence number 124 4209892586
 silly# echo "SHOW INNODB STATUS \G" | mysql -p'xxxxxx' | grep '^Log seq'
 Log sequence number 125 85212387

The big number is an unsigned 32-bit INT which will wrap at 4GB, increasing the smaller number every time. In this case above it just rolled from 124 to 125. Your goal is hidden in the mysqld.log that sent you Googling for this ridiculous solution in the first place. Once you cross that finish line, that's it! Blow the horns! Release the confetti!

Sidebar: This uncovered an interesting bug in mysqld 5.0 w/REPEAT: if you go to 20 MB, it flips some internal counter and rolls over to ~ 96 KB. No warning or error anywhere. I wasn't about to waste time tracking that down. 10 MB works great. If you do hit some other limit, it may complain. I have various innodb buffers increased from default. Season to taste. As always, watch mysqld.log in one window.

EXCERPT

5MB is the default size for innodb_log_file_size. Percona's mysqperformanceblog.com gave two good articles on computing the right size for your particular MySQL instance:

Basically, the blog recommends measuring how many bytes are written to the InnoDB Log Files in one hour. This is what I run to figure that out

SET @TimeInterval = 3600;
SELECT variable_value INTO @num1 FROM information_schema.global_status
WHERE variable_name = 'Innodb_os_log_written';
SELECT SLEEP(@TimeInterval);
SELECT variable_value INTO @num2 FROM information_schema.global_status
WHERE variable_name = 'Innodb_os_log_written';
SET @ByteWrittenToLog = @num2 - @num1;
SET @KB_WL_HR = @ByteWrittenToLog / POWER(1024,1) * 3600 / @TimeInterval;
SET @MB_WL_HR = @ByteWrittenToLog / POWER(1024,2) * 3600 / @TimeInterval;
SET @GB_WL_HR = @ByteWrittenToLog / POWER(1024,3) * 3600 / @TimeInterval;
SELECT @KB_WL_HR,@MB_WL_HR,@GB_WL_HR;

END OF EXCERPT

Where do you go from here?

Run these commands every hour for a week. When you ascertain the highest number for @MB_WL_HR, take half of it and resize innodb_log_file_size to it : See my post How to safely change MySQL innodb variable 'innodb_log_file_size'?

CONCLUSION

Since you can figure out the proper InnoDB Log File Size in this manner, there is no need to pool the show engine innodb status\G for anything, especially since you said it is not available in MySQL 5.0.

Keep in mind that my answer works for MySQL 5.1/5.5. So, how do you did this for MySQL 5.0?

It's a good thing the status variable Innodb_os_log_written exists in MySQL 5.0.

Looking back, here is your original question:

mysql> pager grep sequence
PAGER set to 'grep sequence'

mysql> show engine innodb status\G select sleep(60); show engine innodb status\G
Log sequence number 84 3836410803
1 row in set (0.06 sec)
1 row in set (1 min 0.00 sec)
Log sequence number 84 3838334638
1 row in set (0.05 sec)

mysql> select (3838334638 - 3836410803) / 1024 / 1024 as MB_per_min;
+------------+
| MB_per_min |
+------------+
| 1.83471203 | 
+------------+

With MySQL 5.0 you have to do this:

mysql> show global status like 'Innodb_os_log_written'; select sleep(60); show global status like 'Innodb_os_log_written';

Then subtract and multiply like you did before:

mysql> show global status like 'Innodb_os_log_written'; select sleep(60); show global status like 'Innodb_os_log_written';
+-----------------------+--------------+
| Variable_name         | Value        |
+-----------------------+--------------+
| Innodb_os_log_written | 500034464256 |
+-----------------------+--------------+
1 row in set (0.01 sec)

+-----------+
| sleep(60) |
+-----------+
|         0 |
+-----------+
1 row in set (1 min 0.01 sec)

+-----------------------+--------------+
| Variable_name         | Value        |
+-----------------------+--------------+
| Innodb_os_log_written | 500047017984 |
+-----------------------+--------------+
1 row in set (0.01 sec)

mysql> select (500047017984 - 500034464256) / 1024 / 1024 as MB_per_min;
+-------------+
| MB_per_min  |
+-------------+
| 11.97216797 |
+-------------+
1 row in set (0.00 sec)

mysql>

Give it a Try !!!

MySQL InnoDB logfiles resized – review thesql-err.log for potential problems

It is sort of yes and no. Why would I say both?

There are still some transactional data embedded in the old ib_logfiles in conjunction with the ibdata1 file. (See pictorial representation)

What you should have done is this:

mysql -u... -p... -ANe"SET GLOBAL innodb_fast_shutdown = 0"
/etc/init.d/mysql.server stop
mv ib_logfile0 ib_logfile0.OLD
mv ib_logfile0 ib_logfile0.OLD
/etc/init.d/mysql.server start

If you did not know of disabling innodb_fast_shutdown, ther you steps should have been

/etc/init.d/mysql.server stop
/etc/init.d/mysql.server start
/etc/init.d/mysql.server stop
mv ib_logfile0 ib_logfile0.OLD
mv ib_logfile0 ib_logfile0.OLD
/etc/init.d/mysql.server start

Doing either of these coordinate the purging of all uncommitted writes to tables and indexes. Just looking at the error log, I think you dodged a bullet in this instance. In future, please follow this protocol.

If you are not sure either way, you could put back the old log files, set the old size of innodb_log_file_size, restart mysql. Then, start the process over again as I prescribed above.

Best Answer

Related Solutions

Find Current Log Sequence Number in MySQL 5.0.X

EXCERPT

END OF EXCERPT

CONCLUSION

MySQL InnoDB logfiles resized – review thesql-err.log for potential problems

Related Question