MySQL Bugs: #79663: Improve shutdown reporting of the page cleaner thread.

Bug #79663	Improve shutdown reporting of the page cleaner thread.
Submitted:	16 Dec 2015 10:11	Modified:	5 Jul 2018 8:30
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	5.7.9	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	flushing, page cleaner, progress indicator

Description:
Current logging (from 5.7.9) shows this:

2015-12-16T10:03:18.702765Z 0 [Note] InnoDB: FTS optimize thread exiting.
2015-12-16T10:03:18.702926Z 0 [Note] InnoDB: Starting shutdown...
2015-12-16T10:03:18.808273Z 0 [Note] InnoDB: Dumping buffer pool(s) to /mysql/md/data/ib_buffer_pool
2015-12-16T10:03:19.261104Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 151216 11:03:19
2015-12-16T10:04:20.060183Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2015-12-16T10:05:20.214067Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2015-12-16T10:06:20.368096Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2015-12-16T10:07:20.521607Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
...

There's no indication of the progress and no indication of how long I might need to wait for the process to complete.

How to repeat:
See above.

On a busy box where there are a lot of dirty pages this process can take a long time.

Suggested fix:
Improve logging if possible to given an indication of the page cleaner progress, possibly as a percentage of work to do. You update this periodically so that's good and with some sort of progress indicator the DBA has an idea how long the process is likely to take.

5.7.22 here.
I'm sitting here wait for my test server to shutdown, so googled this.

I just did a load of data,  a big delete, and set innodb_fast_shutdown=0 then shutdown, so I know what it is doing,  but it isn't clear on progress...

Version: '5.7.22'  socket: ''  port: 3306  MySQL Community Server (GPL)
2018-07-05T07:27:44.514583Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4065ms. The settings might not be optimal. (flushed=1751
2018-07-05T07:33:00.690732Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10576ms. The settings might not be optimal. (flushed=109
2018-07-05T07:33:20.741778Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5123ms. The settings might not be optimal. (flushed=917
2018-07-05T07:33:31.955202Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5185ms. The settings might not be optimal. (flushed=905
2018-07-05T08:01:46.635399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4068ms. The settings might not be optimal. (flushed=202
2018-07-05T08:01:48.758669Z 0 [Note] mysqld: Normal shutdown

2018-07-05T08:01:48.762669Z 0 [Note] Giving 1 client threads a chance to die gracefully
2018-07-05T08:01:48.765169Z 0 [Note] Shutting down slave threads
2018-07-05T08:01:50.783426Z 0 [Note] Forcefully disconnecting 1 remaining clients
2018-07-05T08:01:50.783926Z 0 [Warning] mysqld: Forcing close of thread 3  user: 'root'

2018-07-05T08:01:50.785426Z 0 [Note] Binlog end
...
2018-07-05T08:01:50.802928Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2018-07-05T08:01:50.803428Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2018-07-05T08:01:50.804428Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2018-07-05T08:01:50.804928Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2018-07-05T08:01:50.805429Z 0 [Note] Shutting down plugin 'InnoDB'
2018-07-05T08:01:50.805929Z 0 [Note] InnoDB: FTS optimize thread exiting.
2018-07-05T08:01:50.806929Z 0 [Note] InnoDB: Starting shutdown...
2018-07-05T08:01:50.950447Z 0 [Note] InnoDB: Dumping buffer pool(s) to E:\mysql-5.7.22-winx64\data\ib_buffer_pool
2018-07-05T08:01:51.043959Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 180705 10:01:51
2018-07-05T08:02:50.919562Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:03:51.032195Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:04:51.141328Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:05:51.272464Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:06:51.386097Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:07:51.496731Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:08:51.611864Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:09:51.725498Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:10:51.838631Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:11:51.948764Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:12:52.070899Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:13:52.180031Z 0 [Note] InnoDB: Waiting for worker threads to be suspended
2018-07-05T08:15:20.497246Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:16:20.606879Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:17:20.744016Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:18:20.869151Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:19:20.980284Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:20:21.089417Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:21:21.216552Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:22:21.348688Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-07-05T08:23:21.461321Z 0 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool