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;

Fernandefernandel

What's the actual problem? Taking too long is not something I see as bei ng an issue for a one off process! Can you be much more specific, what errors if any are you seeing? Do you have any logs that might indicate what is happening? Sorry, but just no where near enough info for anyone to help – Kaon

What's the actual question? This reads more like a status report than a question. – Kiersten

Sorry for bothering now, but maybe it could be useful to migrated this question to ServerFault - serverfault.com/help/on-topic – Magnetism

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_pages_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

Seguidilla

setting innodb_lru_scan_depth to 256 didn't solve the problem – Dibranchiate

@KarimSamir, there is nothing special about the value 256. It was an example that the OP used. – Seguidilla

yes, I know , can you suggest anything else I can do to solve this problem? – Dibranchiate

@KarimSamir, (1) experiment with other values smaller than 256, (2) get faster storage. – Seguidilla

one more thing how to permanently change innodb_lru_scan_depth ? – Dibranchiate

@KarimSamir, you should edit your server's option file (for example /etc/my.cnf) to save any global options you want to be persistent and applied every time the server starts. dev.mysql.com/doc/refman/5.7/en/option-files.html – Seguidilla

I can't find it at any place at MySQL 5.7 configuration file, so I added to file /etc/mysql/my.cnf [mysqld] innodb_lru_scan_depth=256 after !includedir /etc/mysql/conf.d/ !includedir /etc/mysql/mysql.conf.d/ – Dibranchiate

@BillKarwin - the Page_cleaner blog gets a 404 – Trillium

@RickJames, thanks for noticing, I replaced it with a link to archive.org, and I added a second MySQL Server Team blog about the page cleaner. – Seguidilla

@BillKarwin - What does lru_scan_depth measure? Is it limiting the number of blocks in the buffer_pool to check? The number of blocks in some list? Something else? – Trillium

@RickJames, As the page cleaner searches for pages of the buffer pool to flush, it'll try to scan only lru_scan_depth pages (per BP instance), then it pauses itself until the next iteration. – Seguidilla

@BillKarwin - Then, should lru_scan_depth be somehow tied to io_capacity? That is, will it try to flush 1024 blocks at a whack? – Trillium

@RickJames, InnoDB decides how many pages it wants to flush, as a percentage of io_capacity. So it won't try to flush more than 100% of io_capacity in pages. But then as it tries to do the flushing, it won't scan more pages than lru_scan_depth. – Seguidilla

@BillKarwin - So, increasing io_capacity should be another way to "prevent" the "page_cleaner 1000ms..." error? (Nearly everyone leaves it at 200.) – Trillium

@RickJames, I would think that increasing io_capacity could only cause more occurrences of the page cleaner taking too long and logging an error. – Seguidilla

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.

Beneficial

very detailed explanation, will look in to implementing it. thanks – Hazeghi

@Beneficial Thanks for explanation – Fernandefernandel

GUYS! When using SSD drive, DO NOT FORGET, that speed of writing is almost the same as with normal spin drive.... I did several tests and I'm dissapointed. It really doesn't work faster with database, that is not a "normal" application. Here is an explanation why benchmarks for databases using SSD drives are useless: link. Really, a didn't expect that SSD is soooooo slooow.... – Beneficial

Careful with step 3.2 as I have been read this is not safe for production servers. https://dba.stackexchange.com/questions/86636/when-is-it-safe-to-disable-innodb-doublewrite-buffering Very good post btw, I have been testing the other steps you mentioned, still no luck in my case but it probably helped anyway :) – Futures

@Beneficial MySQL by default is configured to be very conservative on resources, you will need to change the default IO read/write and caching to take advantage of any SSD. The link you posted is for consumer reviews of SSDs being irrelevant for RDBMs purposes. percona.com/blog/2016/09/09/dont-spin-data-use-ssds – Anse

For innodb_flush_log_at_trx_commit, "the default setting of 1 is required for full ACID compliance". Source: dev.mysql.com/doc/refman/5.7/en/… – Polystyrene

Answer 3

This can simply be indicative of poor filesystem performance in general - a symptom of an unrelated problem. In my case I spent an hour researching this, analyzing my system logs, and had nearly reached the point of tweaking the MySQL config, when I decided to check with my cloud based hosting. It turns out there were "abusive I/O spikes from a neighbor." which my host quickly resolved after I brought it to their attention.

My recommendation is to know your baseline / expected filesystem performance, stop MySQL, and measure your filesystem performance to determine if there are more fundamental problems unrelated to MySQL.

Amphibian