How to solve mysql warning: "InnoDB: page_cleaner: 1000ms intended loop took XXX ms. The settings might not be optimal "?

Question

I ran a mysql import mysql dummyctrad < dumpfile.sql on server and its taking too long to complete. The dump file is about 5G. The server is a Centos 6, memory=16G and 8core processors, mysql v 5.7 x64-

Are these normal messages/status "waiting for table flush" and the message InnoDB: page_cleaner: 1000ms intended loop took 4013ms. The settings might not be optimal

mysql log contents

2016-12-13T10:51:39.909382Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4013ms. The settings might not be optimal. (flushed=1438 and evicted=0, during the time.) 2016-12-13T10:53:01.170388Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4055ms. The settings might not be optimal. (flushed=1412 and evicted=0, during the time.) 2016-12-13T11:07:11.728812Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4008ms. The settings might not be optimal. (flushed=1414 and evicted=0, during the time.) 2016-12-13T11:39:54.257618Z 3274915 [Note] Aborted connection 3274915 to db: 'dummyctrad' user: 'root' host: 'localhost' (Got an error writing communication packets) 

Processlist:

mysql> show processlist \G; *************************** 1. row ***************************      Id: 3273081    User: root    Host: localhost      db: dummyctrad Command: Field List    Time: 7580   State: Waiting for table flush    Info:  *************************** 2. row ***************************      Id: 3274915    User: root    Host: localhost      db: dummyctrad Command: Query    Time: 2   State: update    Info: INSERT INTO `radacct` VALUES (351318325,'kxid ge:7186','abcxyz5976c','user100 *************************** 3. row ***************************      Id: 3291591    User: root    Host: localhost      db: NULL Command: Query    Time: 0   State: starting    Info: show processlist *************************** 4. row ***************************      Id: 3291657    User: remoteuser    Host: portal.example.com:32800      db: ctradius Command: Sleep    Time: 2   State:     Info: NULL 4 rows in set (0.00 sec) 

Update-1

mysqlforum ,innodb_lru_scan_depth

changing innodb_lru_scan_depth value to 256 have improved the insert queries execution time + no warning message in log, the default was innodb_lru_scan_depth=1024;

SET GLOBAL innodb_lru_scan_depth=256;

Answer 1

InnoDB: page_cleaner: 1000ms intended loop took 4013ms. The settings might not be optimal. (flushed=1438 and evicted=0, during the time.)

The problem is typical of a MySQL instance where you have a high rate of changes to the database. By running your 5GB import, you're creating dirty pages rapidly. As dirty pages are created, the page cleaner thread is responsible for copying dirty pages from memory to disk.

In your case, I assume you don't do 5GB imports all the time. So this is an exceptionally high rate of data load, and it's temporary. You can probably disregard the warnings, because InnoDB will gradually catch up.

---

Here's a detailed explanation of the internals leading to this warning.

Once per second, the page cleaner scans the buffer pool for dirty pages to flush from the buffer pool to disk. The warning you saw shows that it has lots of dirty pages to flush, and it takes over 4 seconds to flush a batch of them to disk, when it should complete that work in under 1 second. In other words, it's biting off more than it can chew.

You adjusted this by reducing innodb_lru_scan_depth from 1024 to 256. This reduces how far into the buffer pool the page cleaner thread searches for dirty pages during its once-per-second cycle. You're asking it to take smaller bites.

Note that if you have many buffer pool instances, it'll cause flushing to do more work. It bites off innodb_lru_scan_depth amount of work for each buffer pool instance. So you might have inadvertently caused this bottleneck by increasing the number of buffer pools without decreasing the scan depth.

The documentation for innodb_lru_scan_depth says "A setting smaller than the default is generally suitable for most workloads." It sounds like they gave this option a value that's too high by default.

You can place a limit on the IOPS used by background flushing, with the innodb_io_capacity and innodb_io_capacity_max options. The first option is a soft limit on the I/O throughput InnoDB will request. But this limit is flexible; if flushing is falling behind the rate of new dirty page creation, InnoDB will dynamically increase flushing rate beyond this limit. The second option defines a stricter limit on how far InnoDB might increase the flushing rate.

If the rate of flushing can keep up with the average rate of creating new dirty pages, then you'll be okay. But if you consistently create dirty pages faster than they can be flushed, eventually your buffer pool will fill up with dirty pages, until the dirty pages exceeds innodb_max_dirty_page_pct of the buffer pool. At this point, the flushing rate will automatically increase, and may again cause the page_cleaner to send warnings.

Another solution would be to put MySQL on a server with faster disks. You need an I/O system that can handle the throughput demanded by your page flushing.

If you see this warning all the time under average traffic, you might be trying to do too many write queries on this MySQL server. It might be time to scale out, and split the writes over multiple MySQL instances, each with their own disk system.

Read more about the page cleaner:

• Introducing page_cleaner thread in InnoDB (archived copy)
• MySQL-5.7 improves DML oriented workloads

Answer 2

The bottleneck is saving data to HDD. Whatever HDD you have: SSD, normal one, NVMe etc.

Note, that this solution applies mostly to InnoDB

I had the same problem, I've applied few solutions.

1st: checking what's wrong

atop -d will show you disk usage. If disk is 'busy', then try to stop all queries to database (but don't stop mysql server service!)

To monitor how many queries you do have, use mytop, innotop or equivalent.

If you have 0 queries, but disk usage is STILL next to 100% from a few seconds / few minutes, then it means, that mysql server is trying to flush dirty pages / do some cleaning as mentioned before (great post of Bill Karwin).

THEN you can try to apply such solutions:

2nd: harware optimisation

If your array is not in RAID 1+0 consider to double speed of saving data using such kind of solution. Try to extend your HDD cotroller possibilities with writing data. Try to use SSD or faster HDD. Applying this soultion depends on your harware and budget possibilities and may vary.

3nd: software tuning

If harware cotroller is working fine, but you want to extend speed of saving data you can set up in mysql config file:

3.1.

innodb_flush_log_at_trx_commit = 2 -> if you/re using innodb tables It works form my experisnce the best with one table per file: innodb_file_per_table = 1

3.2.

continuing with InnoDB: innodb_flush_method = O_DIRECT innodb_doublewrite = 0 innodb_support_xa = 0 innodb_checksums = 0

Lines above are in general reducing amount of data needed to be saved in HDD, so performance is greater.

3.3

general_log = 0 slow_query_log = 0

Lines above disable saving logs, of course it is yet another amount of data to be saved on HDD

3.4 check again what's happening usit e.g. tail -f /var/log/mysql/error.log

4th: general notes

General notes: This was tested under MySQL 5.6 AND 5.7.22 OS: Debian 9 RAID: 1 + 0 SSD drives Database: InnoDB tables innodb_buffer_pool_size = 120G innodb_buffer_pool_instances = 8 innodb_read_io_threads = 64 innodb_write_io_threads = 64 Total amount of RAM in server: 200GB

After doing that you may observe higher CPU usage; that's normal, because writing data is more faster, so then CPU will work harder.

If you're doing that using my.cnf of course don't forget to restart MySQL server.

5th: supplement

Beeing intrigued I did this quirk with SET GLOBAL innodb_lru_scan_depth=256; mentioned above.

Working with big tables I've seen no change in performance.

After corrections above I didn't get rid of warnings, however whole system is working significantly faster. Everything above is just an experimentation, but I have measured results, it helped me a little, so hopefully it may be useful for others.