Bug #47707 print some progress messages during shutdown of innodb
Submitted: 29 Sep 2009 11:01 Modified: 19 Apr 2012 20:00
Reporter: Shane Bester (Platinum Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S4 (Feature request)
Version:5.1, 5.5 OS:Any
Assigned to: Jimmy Yang CPU Architecture:Any

[29 Sep 2009 11:01] Shane Bester
Description:
090929 12:58:16 [Note] mysqld: Normal shutdown
090929 12:58:18  InnoDB: Starting shutdown...
090929 12:58:34  InnoDB: Shutdown completed; log sequence number 0 2382381277

during innobd shutdown, flushing of pages can take many minutes and server
might appear hung.  this is a feature request to print out more detailed information about progress of shutdown between lines 2 and 3 above.

How to repeat:
make huge innodb pool and fill with data, then shutdown and note a long time passes.
[29 Sep 2009 11:01] MySQL Verification Team
customers got worried when shutdown took 20+ minutes with no indication of what is going on...
[29 Sep 2009 11:16] MySQL Verification Team
related info:

http://www.mysqlperformanceblog.com/2009/04/15/how-to-decrease-innodb-shutdown-times/
[4 Oct 2010 3:09] Jimmy Yang
Fix checked in mysql-trunk-innodb (5.6)

Following messages are added stating the status of server during shutdown:

1) InnoDB: Waiting for srv_monitor_thread (srv_lock_timeout_thread/ srv_error_monitor_thread) to exit
2) InnoDB: Waiting for %lu active transactions to exit
3) InnoDB: Waiting for master thread (worker threads) to be suspended
4) InnoDB: Pending checkpoint_writes: %lu
5) InnoDB: Pending log flush writes: %lu
6) InnoDB: Waiting for %lu buffer page I/Os to complete
7) InnoDB: Waiting for dirty buffer pages to be flushed

8) For both fast/slow shutdown, we also print following progress every 60 seconds:

InnoDB: Waiting for %lu tables to be dropped

9) For slow shutdown, following two message will be printed if we are blocked for such activities:

InnoDB: Waiting for %lu undo logs to be purged
InnoDB: number of pages just purged: %lu

InnoDB: Waiting for change buffer merge to complete\n
InnoDB: number of bytes of change buffer just merged:  %lu
[4 Oct 2010 6:01] James Day
If you're interested in this you may also be interested in bug #48026, a similar feature request for more logging during InnoDB startup.
[4 Oct 2010 6:38] Simon Mudd
Note: this fix is great but doesn't actually address a very similar request made for the general case of mysql shutdown in http://bugs.mysql.com/bug.php?id=34137.

Is there a chance that can be addressed too?
[13 Nov 2010 16:16] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:alexander.nozdrin@oracle.com-20101113152450-2zzcm50e7i4j35v7) (merge vers: 5.6.1-m4) (pib:21)
[13 Nov 2010 16:29] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (pib:21)
[15 Feb 2011 7:17] Jimmy Yang
John, this bug does not have "SR51MRU" nor "SR55MRU" tag. Request for triage, whether it should be back ported to 5.1 and 5.5
[19 Apr 2012 20:00] John Russell
Added to changelog for 5.5.23:

When shutting down the MySQL server, the cleanup operations of
the "InnoDB" shutdown could take a long time
with no output, making the server appear to be hung.

[Note] mysqld: Normal shutdown
InnoDB: Starting shutdown...
InnoDB: Shutdown completed; log sequence number ...

Now additional progress messages are displayed between the
"starting" and "completed" messages:

InnoDB: Waiting for srv_monitor_thread (srv_lock_timeout_thread/ srv_error_monitor_thread) to exit
InnoDB: Waiting for %lu active transactions to exit
InnoDB: Waiting for master thread (worker threads) to be suspended
InnoDB: Pending checkpoint_writes: %lu
InnoDB: Pending log flush writes: %lu
InnoDB: Waiting for %lu buffer page I/Os to complete
InnoDB: Waiting for dirty buffer pages to be flushed

For both "fast shutdown"
and "slow shutdown", a
progress messages is printed every 60 seconds:

InnoDB: Waiting for %lu tables to be dropped

During a slow shutdown, two additional messages are printed if
certain phases take longer than normal:

InnoDB: Waiting for %lu undo logs to be purged
InnoDB: number of pages just purged: %lu

InnoDB: Waiting for change buffer merge to complete\n
InnoDB: number of bytes of change buffer just merged: %lu