MySQL Bugs: #48026: Log start and end of InnoDB buffer pool initialization to the error log

Bug #48026	Log start and end of InnoDB buffer pool initialization to the error log
Submitted:	13 Oct 2009 15:50	Modified:	14 Dec 2010 19:12
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.1, 5.4	OS:	Any
Assigned to:	Jimmy Yang	CPU Architecture:	Any

Description:
It would be nice to have timestamps for the beginning and ending of InnoDB buffer pool initialization in the error log. Like this:

YYMMDD HH:MM:SS InnoDB: Initializing buffer pool, size = 10G
YYMMDD HH:MM:SS InnoDB: Completed initialization of buffer pool

With innodb_buffer_pool_size of 10G and up, initialization takes notable time (6+ seconds on modern hardware), and it would be nice to know why server starts up so long and at what startup stage InnoDB is.

How to repeat:
Start InnoDB with huge buffer pool after crash with some transactions not fixed and after normal shutdown. Try to find out how much time, exactly, was spent on buffer pool initialization in both cases.

Message will be printed in following format:

100818 20:05:54 InnoDB: Initializing buffer pool, size = 1.9G
100818 20:05:54 InnoDB: Completed initialization of buffer pool

100818 20:08:11 InnoDB: Initializing buffer pool, size = 19.0M
100818 20:08:11 InnoDB: Completed initialization of buffer pool

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116162

3167 Jimmy Yang	2010-08-18
      Fix Bug #48026  Log start and end of InnoDB buffer pool initialization to
      the error log.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/116163

3167 Jimmy Yang	2010-08-18
      Bug #48026 Log start and end of InnoDB buffer pool initialization to
      the error log

It's not clear from the public comments as to which versions will get this new patch (5.1 or 5.4 or both?). Could you clarify that?

This patch will be in 5.5.7 release. 5.4 does not exist anymore.

Sorry, when I replied I was looking at the Version: section of this bug which mentions 5.1, 5.4. (I reported this bug via MySQL support which is why I'm not the reporter.)

Thanks for reporting that the bug will be in 5.5.7, but I'd also like to see this in 5.1 which is the current GA version and the version which I was using when originally reporting the problem. We're still using that version and since Oracle is unwilling to state when 5.5 will go GA, I'd like to actually see this fix in a time frame I can plan for.

Simon, we've announced that 5.5 will be GA this year. The precision of that timeline is improving rapidly as we approach year end and we have a release candidate in place already.

It'll still take a while before people migrate from 5.1 to 5.5, so doing this in 5.1 is likely to be useful for another year or two. Those who want more performance or fewer database servers will face significant performance pressure to migrate as quickly as they prudently can, because of the performance change in 5.5 compared to 5.1.

Anyone interested in this feature request may also want to look at bug #47707, doing the same during InnoDB shutdown.

Added to 5.5.7 change log:

InnoDB startup messages now include the start and end times for
buffer pool initialization, and the total buffer pool size.

Pushed into mysql-5.5 5.5.7-rc (revid:sunanda.menon@sun.com-20101109182959-otkxq8vo2dcd13la) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)

Fix ported to 5.1 built-in and plugin (mysql-5.1-innodb)

Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)

Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (pib:21)

Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (version source revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (merge vers: 5.6.1) (pib:23)

Added to 5.1.54 change log too.

Pushed into mysql-5.1 5.1.55 (revid:sunanda.menon@oracle.com-20101215054055-vgwki317xg1wphhh) (version source revid:sunanda.menon@oracle.com-20101215054055-vgwki317xg1wphhh) (merge vers: 5.1.55) (pib:23)

Pushed into mysql-5.5 5.5.9 (revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (version source revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (merge vers: 5.5.9) (pib:24)