MySQL Bugs: #76661: Improve help when reporting page cleaner loop taking too long

Bug #76661	Improve help when reporting page cleaner loop taking too long
Submitted:	10 Apr 2015 19:50	Modified:	18 Sep 2018 10:34
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.6,5.7.7,5.7.8, 5.7.14,5.7.17,8.0.1	OS:	Linux (CentOS 6)
Assigned to:		CPU Architecture:	Any
Tags:	5.7.17, 5.7.6, 5.7.7, 5.7.8, 8.0.1, logging, page_cleaner, reporting

Description:
I have a busy server which I've just upgraded to 5.7.7.

I notice periodic reporting of messages like the following:

2015-04-10T13:19:31.056938Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4313ms. The settings might not be optimal. (flushed=343 and evicted=1290, during the time.)
2015-04-10T13:19:54.703120Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4645ms. The settings might not be optimal. (flushed=343 and evicted=1009, during the time.)
2015-04-10T13:49:35.953917Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4045ms. The settings might not be optimal. (flushed=343 and evicted=15112, during the time.)
...

There aren't a huge number of these messages but if you're going to indicate an issue it might be helpful to provide a URL to give a better description of the potential "problem",
and possible configuration issues and solutions for this.

I see 46 entries in 14 hours and it looks like some of these entries were also issues by 5.7.6 too before I did the upgrade.

How to repeat:
Upgrade to 5.7.7 and run some heavy queries... (but not sure how to reproduce)

The server concerned does heavy aggregation of data in parallel threads and is usually i/o bound for several hours. The disk subsystem is already using SSDs to improve this and the batch type processing that's ongoing as indicated takes several hours to run. The server has 192 GB of RAM and the data set being processed is about 2 TB.

I can provide more detailed configuration information if needed in private. The point here is not really about my specific setup but helping the user understand the problem at hand and then being able to adjust his setup to try to prevent the reported "issue".

It's quite possible that my configuration is sub-optimal so it's good to see a report that there's a problem but the report seems intended/focussed on what a MySQL developer wants to see and is not helpful for a DBA.

Suggested fix:
1. Provide a URL which describes this type of issue. You're reporting it so you think something is wrong.
2. In that url/page provide info on which settings may be related to the problem, and how to adjust them (and measure the effect of the adjustment) so that the configuration can be improved.

Whether useful or relevant I'm not sure but I notice these reports tend to come in threes shortly spaced apart, and the i/o rates seem to vary quite significantly.

2015-04-10T02:23:24.572965Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6467ms. The settings might not be optimal. (flushed=10045 and evicted=0, during the time.)
2015-04-10T02:23:59.888889Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5448ms. The settings might not be optimal. (flushed=10417 and evicted=12947, during the time.)
2015-04-10T02:24:07.105795Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5217ms. The settings might not be optimal. (flushed=10296 and evicted=9897, during the time.)
2015-04-10T02:45:13.758208Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4567ms. The settings might not be optimal. (flushed=10278 and evicted=7830, during the time.)
2015-04-10T02:45:48.994279Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4234ms. The settings might not be optimal. (flushed=10662 and evicted=11385, during the time.)
2015-04-10T02:45:55.515532Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5521ms. The settings might not be optimal. (flushed=10530 and evicted=10760, during the time.)

Obviously you don't have information on what the application is doing but you can see the I/O rates here are quite a bit higher (same config) though these numbers were from last night's run
when the server was still running 5.7.6.

related:
http://bugs.mysql.com/bug.php?id=76871 (purge, change buffer, page cleaner threads be more verbose during long shutdown)

Hello Simon Mudd,

Thank you for the feature request.

Thanks,
Umesh

This is still present in 5.7.8 and still rather confusing.

# grep page_cleaner /var/log/mysqld.log
2015-08-19T03:30:09.150924Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4467ms. The settings might not be optimal. (flushed=43 and evicted=0, during the time.)
2015-08-19T05:52:04.972220Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8707ms. The settings might not be optimal. (flushed=6769 and evicted=0, during the time.)
2015-08-19T05:52:28.258575Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 12160ms. The settings might not be optimal. (flushed=8742 and evicted=0, during the time.)
2015-08-19T05:52:48.034141Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10769ms. The settings might not be optimal. (flushed=8469 and evicted=0, during the time.)
2015-08-19T05:53:06.580698Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10074ms. The settings might not be optimal. (flushed=9180 and evicted=0, during the time.)

I noticed an old blog post about page cleaners here: https://blogs.oracle.com/mysqlinnodb/entry/introducing_page_cleaner_thread_in and wonder if a new post from the MySQL server team talking about the changes might be helpful, but changing the error message to include a link to some sort of appropriate documentation still seems like the most sensible solution.

would be nice to have some status variable or performance_schema instrument to look at to figure out how often the page cleaner thread took too long.

if tuning the page cleaner should be described in the manual,  then we may request innodb devs to provide some insight or a blog post about how to measure, tune server to avoid seeing this warning.

--

2016-08-10T06:14:45.527581Z 0 [Note] bin/mysqld: ready for connections.
Version: '5.7.14-enterprise-commercial-advanced'  socket: '/tmp/mysql_ushastry.sock'  port: 3306  MySQL Enterprise Server - Advanced Edition (Commercial)
2016-08-10T06:15:09.350552Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 13330ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

On a very quiet slave I get these messages repeatedly on 5.7.14.

CPU and IO are basically ZERO.

4G buffer pool
innodb_page_cleaners defaulting to 4
innodb_buffer_pool_instances defaulting to 8
2016-08-30T16:40:19.790965Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 33997ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-08-30T16:41:19.792951Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 33998ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-08-30T16:42:19.793459Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 33997ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-08-30T16:43:19.795862Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 34000ms. The settings might not be optimal. (flushed=33 and evicted=0, during the time.)
2016-08-30T16:44:19.796439Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 33999ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

Bug #82802 marked as duplicate of this

I'm not sure that my issue (Bug #82802) is a duplicate.

My issues are happening without load and are basically identical each time.

This pops up instantly after upgrading to 5.7.15 as well.

Again this is on a server with no work.

2016-09-06T16:55:35.164733Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35997ms. The settings might not be optimal. (flushed=25 and evicted=0, during the time.)
2016-09-06T16:56:35.166902Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35998ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T16:57:35.166293Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35996ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T16:58:35.167015Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35990ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T16:59:35.165978Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35998ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:00:35.167855Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35999ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:01:35.167986Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35995ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:02:35.168310Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35996ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:03:35.169839Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35991ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:04:35.168964Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35995ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:05:35.169135Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35997ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2016-09-06T17:06:35.169458Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 35990ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

on windows, trunk, with no disk i/o going on.

2016-09-15T13:33:56.039889Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5438ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:35:57.458973Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4377ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:37:08.153867Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7701ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:37:28.725179Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6284ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:38:00.396224Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4619ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:39:47.505707Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4097ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:41:57.592777Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6327ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:43:38.791088Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4599ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T13:44:49.990045Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6558ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:20:26.558838Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4066ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:20:56.961434Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7073ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:21:15.345996Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4834ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:22:39.182291Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4150ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:23:31.555971Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4098ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:25:23.753299Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4200ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:26:06.916609Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4249ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T14:26:33.952136Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6072ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T15:00:09.921664Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7718ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T15:33:53.891079Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 9399ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:07:25.652117Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6376ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:08:15.860633Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4101ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:09:44.732191Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4062ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:10:12.005192Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6148ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:15:07.417271Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6738ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:15:31.659488Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4207ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:16:59.852343Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4266ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:20:11.675103Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4034ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:22:10.638622Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5975ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:22:19.978152Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5338ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:23:32.565768Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5076ms. The settings might not be optimal. (flushed=0 and evicted=0,
2016-09-15T16:24:17.845350Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8445ms. The settings might not be optimal. (flushed=0 and evicted=0,

Have the same

2016-10-21T18:45:38.712305Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4452ms. The settings might not be
 optimal. (flushed=0 and evicted=0, during the time.)
2016-10-21T18:45:52.569978Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4386ms. The settings might not be
 optimal. (flushed=0 and evicted=0, during the time.)
2016-10-21T18:47:52.403963Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7081ms. The settings might not be
 optimal. (flushed=0 and evicted=0, during the time.)

Worst thing is - mysql does not work propertly. Then this error appear server stops responding and all requests goes timeout.

something is faulty with the timing of these messages.  5.7.17-win32 on an idle workstation:

2016-12-15T01:01:57.029398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.030398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.030398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.030398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.031398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.031398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.031398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.032398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.032398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.032398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.032398Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.033399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.033399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.033399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.034399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.034399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.034399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.034399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.035399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.035399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.035399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.035399Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.100402Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.101402Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.102402Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.102402Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.103403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.103403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.103403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.104403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.104403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.104403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.105403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.105403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.105403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.105403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.106403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.106403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.106403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.107403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.107403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.107403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.108403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.108403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.108403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.108403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.109403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.
2016-12-15T01:01:57.109403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 0ms.

Just saw this message as a part of  #75517 on version 5.7.16.

On: mysqld  Ver 5.7.17 for Linux on x86_64 (MySQL Community Server (GPL))

2017-01-26T09:02:45.742198Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4140ms. The settings might not be optimal. (flushed=179 and evicted=0, during the time.)
2017-01-26T09:03:07.986097Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6104ms. The settings might not be optimal. (flushed=175 and evicted=0, during the time.)
2017-01-26T10:02:41.165380Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4806ms. The settings might not be optimal. (flushed=192 and evicted=0, during the time.)
2017-01-26T10:02:52.713252Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5198ms. The settings might not be optimal. (flushed=175 and evicted=0, during the time.)
2017-01-26T10:35:43.795914Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4022ms. The settings might not be optimal. (flushed=8 and evicted=0, during the time.)
2017-01-26T10:35:54.076641Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5670ms. The settings might not be optimal. (flushed=7 and evicted=0, during the time.)
2017-01-26T12:02:39.167671Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4003ms. The settings might not be optimal. (flushed=8 and evicted=0, during the time.)
2017-01-26T12:02:49.949118Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 9782ms. The settings might not be optimal. (flushed=177 and evicted=0, during the time.)
2017-01-26T12:11:21.519384Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 9760ms. The settings might not be optimal. (flushed=180 and evicted=0, during the time.)
2017-01-26T12:11:30.469508Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6950ms. The settings might not be optimal. (flushed=180 and evicted=0, during the time.)
2017-01-26T12:39:08.904486Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4881ms. The settings might not be optimal. (flushed=8 and evicted=0, during the time.)
2017-01-26T13:56:43.520011Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7886ms. The settings might not be optimal. (flushed=200 and evicted=0, during the time.)
2017-01-26T13:56:56.292736Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5890ms. The settings might not be optimal. (flushed=181 and evicted=0, during the time.)
2017-01-26T14:12:00.391264Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4322ms. The settings might not be optimal. (flushed=8 and evicted=0, during the time.)
2017-01-26T14:12:16.012391Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4303ms. The settings might not be optimal. (flushed=8 and evicted=0, during the time.)
2017-01-26T17:55:58.755015Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4796ms. The settings might not be optimal. (flushed=200 and evicted=0, during the time.)
2017-01-26T21:14:50.002529Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 6640ms. The settings might not be optimal. (flushed=197 and evicted=0, during the time.)
2017-01-26T21:21:42.567273Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5252ms. The settings might not be optimal. (flushed=200 and evicted=0, during the time.)
2017-01-26T21:31:50.637096Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5204ms. The settings might not be optimal. (flushed=200 and evicted=0, during the time.)
2017-01-26T21:32:03.347986Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8710ms. The settings might not be optimal. (flushed=185 and evicted=0, during the time.)

Also present in 8.0.1.

In our case this is printed out when the slave server is processing an ALTER TABLE from master:

ALTER TABLE my_table ENGINE=INNODB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=16, LOCK=NONE;

There's no other traffic on this slave, no reads, just the slave thread doing the ALTER TABLE. When I look at the filesystem, the temporary #*.ibd file is not growing and mysql is without any CPU activity. After a few minutes, the ALTER TABLE finishes and replication continues as usual.

2017-08-11T14:46:28.488101Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4034ms. The settings might not be optimal. (flushed=30016, during the time.)
2017-08-11T14:52:37.794196Z 2460097 [Note] Multi-threaded slave statistics for channel '': seconds elapsed = 822; events assigned = 5142122497; worker queues filled over overrun level = 8503897; waited due a Worker queue full = 2691987; waited due the total size = 0; waited at clock conflicts = 0 waited (count) when Workers occupied = 83644234 waited when Workers occupied = 0

Encountering the same issue on v5.7.18 MySQL Community Edition

With regards to my observation from "[15 Sep 2016 16:40]"...

I was sitting here now in quiet office, and noticed that due to lack of I/O on my datadir (which is dedicated disk), the hard drive was powering down.  

So when the page cleaner ran after a while, there was a pause while disk spins up again, which can be heard since machine is on my desk...

Hi,

Found this issue in 5.7.19
2017-10-25T09:04:02.328403Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4091ms. The settings might not be optimal. (flushed=324 and evicted=0, during the time.)
2017-10-25T09:05:27.997634Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5044ms. The settings might not be optimal. (flushed=382 and evicted=0, during the time.)
2017-10-25T09:07:56.710376Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4005ms. The settings might not be optimal. (flushed=303 and evicted=0, during the time.)
2017-10-25T09:08:45.155857Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5841ms. The settings might not be optimal. (flushed=339 and evicted=0, during the time.)

Thought of downgrading to 5.7.13, same issue appears, need to know, can this crash a server?

As we recently had a server crash too

From an earlier comment:
> 2016-08-10T06:15:09.350552Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 13330ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

Maybe changing this messages from Note to Debug if flushed=0 and evicted=0 would make this slightly less noisy? (could happen on laptop or vm resume)

Added 5.7.17 (even if it's a bit old)

Seen on a busy master of the version indicated above by a colleague:

[colleague@master ~]$ sudo grep page_cleaner /var/log/mysqld.log
2017-11-26T08:34:12.194419Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8553ms. The settings might not be optimal. (flushed=7496 and evicted=0, during the time.)
2017-11-26T08:58:56.182131Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10255ms. The settings might not be optimal. (flushed=16177 and evicted=0, during the time.)
2017-11-26T09:26:08.789073Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4365ms. The settings might not be optimal. (flushed=2635 and evicted=0, during the time.)
2017-11-26T09:26:51.670082Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5633ms. The settings might not be optimal. (flushed=6655 and evicted=0, during the time.)
2017-11-26T09:27:43.839678Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 19237ms. The settings might not be optimal. (flushed=19090 and evicted=0, during the time.)
2017-11-26T11:51:42.587795Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10561ms. The settings might not be optimal. (flushed=8862 and evicted=0, during the time.)
2017-11-26T12:37:36.902666Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 8063ms. The settings might not be optimal. (flushed=11985 and evicted=0, during the time.)
2017-11-26T14:05:11.324469Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4384ms. The settings might not be optimal. (flushed=7534 and evicted=0, during the time.)
2017-11-26T14:05:16.535598Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4211ms. The settings might not be optimal. (flushed=3788 and evicted=0, during the time.)
2017-11-26T14:56:38.012737Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4358ms. The settings might not be optimal. (flushed=3980 and evicted=0, during the time.)
2017-11-26T17:30:18.440109Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7959ms. The settings might not be optimal. (flushed=7835 and evicted=0, during the time.)

I notice the server is running with a low value for innodb_purge_threads, 1, but this is not a dynamic setting (the /etc/my.cnf file has 4 but the server has not been restarted) to pick up the change.

Note: the S4 feature request is for _documentation_ on what to do if you see this and how to adjust the configuration to avoid the problem.

What I find somewhat surprising is to not see an answer to this question after 2 1/2 years.

It seems there are two different times when this error report is seen, one is on an idle server and the other is on a busy server. It's not 100% clear if anything is wrong but the developer who wrote this message clearly wanted to communicate something to the reader as he/she thought that something was wrong and some configuration adjustment is needed.

What change is recommended and the reason for performing that change is still not clear as I would much rather see that recommendation (or a pointer to it) than seeing this message which indicates a problem but not how to resolve it.

Should I make a separate bug report about behaviour? The problem is this warning generated a lot of noise which is a pain and on a server which is not busy perhaps the issue is not important. The issue on a busy server seems to indicate a behaviour which the server developers don't expect and which is therefore an error or unwanted behaviour whiich perhaps means this bug report should be changed to a "problem" and handled as a failure...

Clearly I'm not the only one to see this, so please can we change the triage D5 to something more appropriate especially as this has been seen in 8.0 too?

On:mysql  Ver 14.14 Distrib 5.7.23, for linux-glibc2.12 (x86_64) using  EditLine wrapper

2018-09-17T21:49:16.099053+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7949ms. The settings might not be optimal. (flushed=115 and evicted=0, during the time.)
2018-09-17T21:49:32.874032+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 14775ms. The settings might not be optimal. (flushed=13 and evicted=0, during the time.)
2018-09-17T21:49:44.721204+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 5847ms. The settings might not be optimal. (flushed=6 and evicted=0, during the time.)
2018-09-17T21:49:58.398618+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 12677ms. The settings might not be optimal. (flushed=5 and evicted=0, during the time.)
2018-09-17T21:50:15.610625+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 16212ms. The settings might not be optimal. (flushed=4 and evicted=0, during the time.)
2018-09-17T21:50:31.888889+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 13277ms. The settings might not be optimal. (flushed=99 and evicted=0, during the time.)
2018-09-17T21:51:16.994844+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 10720ms. The settings might not be optimal. (flushed=113 and evicted=0, during the time.)
2018-09-17T21:51:37.524876+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 16530ms. The settings might not be optimal. (flushed=3 and evicted=0, during the time.)
2018-09-17T21:51:49.264016+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 7739ms. The settings might not be optimal. (flushed=4 and evicted=0, during the time.)

I had hoped something would come out of this over the last 3 years but guess that was over-optimistic.

If there's no apparent intention to document what should be done with this message,  can we just change this to be shown at a different loglevel (debug level) so the message won't normally be seen? That would make the noise go away, keep the users happy (even if the server seems to be "stalling unexpectedly") as right now this is just noise.

Note: dragnet logging could be used to filter this out in 8.0 if it's visible in 8.0 GA versions. An example on how to do this might be interesting.

The message was removed in the 8.0 GA version IIRC.

Hi Sunny,

If it was removed from 8.0 GA, maybe it's time to remove it from 5.7? I'd expect the "logging patch" to be minimal and you'd probably make a lot of people happy.

Let me ask for opinions within the team. If nobody objects them time to let go :-)

Hi everyone, I'm running the following setup:

Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips PHP/7.2.15 with MySQL Server version: 8.0.16 - MySQL Community Server - GPL

And sometimes I see on my mysql.log file the following line:

2019-11-09T02:45:17.964231-03:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7202ms to flush 200 and evict 0 pages

I believe it is related to this bug/issue.

I changed innodb_lru_scan_depth from 1024 to 256 and it is still happening.

Most of the time when this happens, is not a problem, but sometimes it generates a peak of usage on my server and the following message appears to my users:

"Uncaught PHP Exception PDOException: "SQLSTATE[08004] [1040] Too many connections" at /www/_old/libs/Config.class.php line 301".

Due to this is that I believe this has to be addressed somehow.

Thanks in advance