MySQL Bugs: #70613: "Database was not shut down normally! " after changing innodb_log_file

Bug #70613	"Database was not shut down normally! " after changing innodb_log_file_size
Submitted:	14 Oct 2013 7:38	Modified:	17 Oct 2013 6:23
Reporter:	Area sistemi Ripartizione Informatica	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.1	OS:	Linux
Assigned to:		CPU Architecture:	Any

Description:
I followed Mysql documentation about changing innodb_log_file_size (I tested this procedure also with innodb_fast_shutdown set to 0) and when I start db all seems to be ok but from logs I can see:

131002 08:04:58 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
131002 8:04:58 InnoDB: Initializing buffer pool, size = 8.0M
131002 8:04:58 InnoDB: Completed initialization of buffer pool
131002 8:04:58 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 10 MB
InnoDB: Database physically writes the file full: wait...
131002 8:04:58 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
131002 8:04:58 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...
131002 8:05:05 InnoDB: Started; log sequence number 3 1342899212

The question is: it is an exptected behavior the fact that db starts anyway in crash recovery? 
Is it a bug?

How to repeat:
http://dev.mysql.com/doc/refman/5.1/en/innodb-data-log-reconfiguration.html

Hi,

You have followed a procedure from the manual properly. However, it seems that something went wrong during shutdown.

Please, set log files sizes back to the original ones. Set fast shutdown option to 0, copy back the original log files back over new ones. Then start server, make a mysqldump or ibbackup (just in case) and then shut down server with:

mysqladmin shutdown

Don't reboot your machine until mysqladmin finishes the shutdown.

First, before you re-start your server, check the error log if everything has finished without any errors or warnings. 

If there are any errors or warnings, report them back.

If there are no error or warnings in the error log file, then repeat the procedure for changing log file sizes again and let us know how did it proceed.

I restored the original scenario (I did a clone of my production host in my VM environment).
I repeated the step in the manual to resize innodb_log_file_size and I used "mysqladmin shutdown" to shut the db instead of /etc/init.d/mysqld service but the result was the same. Moreover I set "fast shutdown option to 0".
In the log I can always read the same messages (normal shutdown and then crash recovery).

shutdown and startup logs

Attachment: mysqld.log (text/x-log), 1.60 KiB.

Then LSN changed, hence the warning:

131015  8:44:59  InnoDB: Shutdown completed; log sequence number 0 980646559
...
131015  8:46:42  InnoDB: Started; log sequence number 0 980646924

Same thing was reported in http://bugs.mysql.com/bug.php?id=37391 but I'm not sure that was closed with a good enough explanation.

Hi!

Did you have fast shutdown set to 0 , prior to starting up of the server with old log files ??? Please, make sure of that. Fast shutdown must be 0 before server is started with old log file sizes.

You should do one more test in which you would cut off all innoDB activity for several seconds prior to the slow shutdown. You should also let us know of the free space on the partitions where central tablespace is. Are all of your tables in their own files, or are there some in the central tablespace ???

Also, please, send us your my.cnf as it was with old log file sizes and my.cnf with new log file sizes.

One last and most important question. Did the server with changed log file sizes start or not ???

I made the tests you suggested and the result is always the same.
My partion has enough free space (above 1.1GB) and the resize was done from 5MB to 10MB.
My tables are on their own files (innodb_file_per_table).

The most important thing is, as you asked to me,  that mysql, after resizing, seems to start without problems.

Thanks for your support.

(Marco Pallotta)

my.cnf pre resizing

Attachment: my.cnf.pre (application/octet-stream, text), 550 bytes.

post resizing

Attachment: my.cnf (application/octet-stream, text), 575 bytes.

In cases like yours, if server continues running after all these error messages, then it is fully expected behavior.

Problem is that Log Sequence Numbers are written in the log files as well. So, after you remove the old log files, new ones are created with different Log Sequence Numbers. Hence, a discrepancy that has to be reported.

But, our server then syncs the LSNs and continue running.

So, just continue using a server, as there are actually no problems when server starts running.

Ok. Thanks for your replies.

Regards.

(Marco Pallotta)