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

innodbMySQLrecovery

I restarted mysqld this morning, to increase the size of the innodb logs and increase the amount of memory allocated to the innodb buffer pool. (MySQL 5.1.53-Community on Ubuntu)

To increase the size of the innodb logs, I modified the my.cnf file, stopped mysqld, renamed the existing innodb log files, and then started mysqld again.

     root@mysql01:# /etc/init.d/mysql.server stop
     Shutting down MySQL
     ............ *
     root@mysql01:# ls -al ib_logfile*
     -rw-rw----  1 mysql mysql  251658240 2013-02-08 08:21 ib_logfile0
     -rw-rw----  1 mysql mysql  251658240 2013-02-08 08:21 ib_logfile1
     root@mysql01:# mv ib_logfile0 ib_logfile0.OLD
     root@mysql01:# mv ib_logfile1 ib_logfile1.OLD
     root@mysql01:# /etc/init.d/mysql.server start
     Starting MySQL
     ................................ *
     root@mysql01:#

The mysql01-err.log shows

130208  8:21:27 [Note] /opt/mysql/bin/mysqld: Normal shutdown

130208  8:21:27 [Note] Event Scheduler: Purging the queue. 0 events
130208  8:21:30  InnoDB: Starting shutdown...
130208  8:21:39  InnoDB: Shutdown completed; log sequence number 661 1658279774
130208  8:21:39 [Note] /opt/mysql/bin/mysqld: Shutdown complete

130208 08:21:39 mysqld_safe mysqld from pid file /opt/mysql_data/mysql01.pid ended
130208 08:22:17 mysqld_safe Starting mysqld daemon with databases from /opt/mysql_data
130208  8:22:17 [Note] Plugin 'FEDERATED' is disabled.
130208  8:22:18  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 1536 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300 1400 1500
130208  8:22:29  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 1536 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300 1400 1500
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
130208  8:22:37  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Last MySQL binlog file position 0 886154568, file name ./mysql-bin.001636
130208  8:22:48  InnoDB: Started; log sequence number 661 1658279948
130208  8:22:48 [Note] Event Scheduler: Loaded 0 events
130208  8:22:48 [Note] /opt/mysql/bin/mysqld: ready for connections.
Version: '5.1.53-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)

I'm concerned with the line, after the new innodb log files are written, that says

130208  8:22:37  InnoDB: Database was not shut down normally!

My questions are:

Is that line expected in the log file, is this the behavior I should expect? Does this indicate a problem, or is this a normal result from creating new log files?

Is there anything in the tail of the mysql01-err.log that indicates that there was a real problem?

Was the InnoDB "crash recovery" successful? Or is there a chance that something is screwed up?

Are there any additional steps that I can take to verify that everything is fine with InnoDB, and that the steps I performed did not cause any corruption?

(I'd rather know about any problems now. It would be much better to do any additional steps to get a full recovery, sooner, rather than later.)

Best Answer

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.

Related Solutions

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

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.

Thesql cannot start because of init.d folder

In the first one it is looking for a DB in /var/lib/mysql (the default) and in the second, it is looking in /data/mysql, where you have moved to.

Best Answer

Related Solutions

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

Thesql cannot start because of init.d folder

Related Question