mariadb – Resolving High Disk Write Rates in MariaDB 10.3

iomariadb

With the help of some other fine people here, I have found the high loads we have been experiencing lately are related to mysqld high disk write rate seen in iotop. With a load average now 3-6 where it used to stay around one. I installed mytop to watch all as constant disk writes are reported in iotop and really don't see much activity at all:

MySQL on localhost (10.3.7-MariaDB-log)                                          up 0+01:09:53 [11:58:50]
Queries: 959.6k  qps:  234 Slow:   125.0         Se/In/Up/De(%):    129/01/02/00
         qps now:  100 Slow qps: 0.0  Threads:    3 (   6/   2) 113/00/03/00
Cache Hits: 357.2k Hits/s: 87.2 Hits now:  22.4  Ratio: 28.8% Ratio now: 19.7%
Key Efficiency: 100.0%  Bps in/out: 127.0k/ 1.9M   Now in/out: 73.4k/901.5k

  Id      User         Host/IP         DB      Time    Cmd Query or State
   --      ----         -------         --      ----    --- ----------
    1 system us                                    0 Daemon InnoDB purge coordinator
    2 system us                                    0 Daemon InnoDB purge worker
    3 system us                                    0 Daemon InnoDB purge worker
    4 system us                                    0 Daemon InnoDB purge worker
    5 system us                                    0 Daemon InnoDB shutdown handler
 5968      root       localhost   wmnf_www         0  Query show full processlist
 6616    wmnfdb       localhost   wmnf_www         0  Sleep

When iotop looks like this:

Total DISK READ :       0.00 B/s | Total DISK WRITE :    1638.41 K/s
Actual DISK READ:       0.00 B/s | Actual DISK WRITE:    1852.28 K/s
 TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
 4075 be/3 root        0.00 B/s    3.82 K/s  0.00 % 34.67 % [jbd2/sdc-8]
 7745 be/4 mysql       0.00 B/s 1497.10 K/s  0.00 %  3.73 % mysqld
 7747 be/4 mysql       0.00 B/s   30.55 K/s  0.00 %  2.34 % mysqld
 7748 be/4 mysql       0.00 B/s   45.83 K/s  0.00 %  1.92 % mysqld
 7741 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  1.64 % mysqld
 7746 be/4 mysql       0.00 B/s   30.55 K/s  0.00 %  0.21 % mysqld
 7742 be/4 mysql       0.00 B/s    0.00 B/s  0.00 %  0.08 % mysqld
14410 be/4 mysql       0.00 B/s   15.28 K/s  0.00 %  0.00 % mysqld

I always see several processes constantly doing disk writes. I did increase the innodb_buffer_pool_size recently, here are the complete settings, all settings after the innodb_ variables are things I've been trying after running mysqltuner with no real help:

[mysqld]
datadir=/db/mysql
tmpdir=/dev/shm
socket=/var/lib/mysql/mysql.sock
max_connections=125
symbolic-links=0
max_allowed_packet=512M
innodb_file_per_table
innodb_flush_method=O_DIRECT
innodb_buffer_pool_size=6G
innodb_log_file_size=1500M
innodb_buffer_pool_instances=6
query_cache_size=16M
query_cache_type=1
thread_cache_size=4
join_buffer_size=16M
tmp_table_size=256M
max_heap_table_size=256M

Is it possible the InnoDB purge processes are causing such high disk writes? This is a WordPress sites and I've been watching the slow queries log, a few here and there, but nothing correlates with the high loads seen.

Here is what top looks like most of the time:

top - 12:16:43 up 13:02,  3 users,  load average: 5.32, 4.26, 4.25
Tasks: 202 total,   6 running, 131 sleeping,   0 stopped,   0 zombie
%Cpu(s): 15.5 us,  5.7 sy,  0.0 ni, 38.3 id,  1.2 wa,  0.0 hi,  0.5 si, 38.8 st
KiB Mem : 16419324 total,   289672 free,  4549808 used, 11579844 buff/cache
KiB Swap:   524284 total,   524284 free,        0 used. 11506900 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 7731 mysql     20   0   10.1g   2.7g  20896 S  28.8 17.2  29:29.86 mysqld
15121 wmnf_ad+  20   0  724508 107340  81852 S  27.2  0.7   0:01.83 httpd
15085 wmnf_ad+  20   0  652008 115456  79932 R  22.2  0.7   0:01.90 httpd
15119 wmnf_ad+  20   0  733080 111168  78336 S  11.9  0.7   0:02.73 httpd
14776 wmnf_ad+  20   0  733724 126108  91168 S  10.9  0.8   0:05.19 httpd
14985 wmnf_ad+  20   0  736768 119092  83020 S   9.6  0.7   0:02.72 httpd
14993 wmnf_ad+  20   0  733832 118872  83732 S   9.6  0.7   0:05.91 httpd
14744 wmnf_ad+  20   0  735768 129408  92820 S   8.6  0.8   0:05.60 httpd
13914 wmnf_ad+  20   0  739364 131340  92704 S   7.9  0.8   0:14.55 httpd
14948 wmnf_ad+  20   0  732920 110984  77456 R   6.3  0.7   0:03.08 httpd

I do see innodb is writing to these ibd files while nothing in the process list, here is what the SHOW ENGINE INNODB STATUS shows:

    =====================================
2018-05-29 12:40:26 0x7ff100325700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 7 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 5814 srv_active, 0 srv_shutdown, 527 srv_idle
srv_master_thread log flush and writes: 6338
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1030737
OS WAIT ARRAY INFO: signal count 588517
RW-shared spins 0, rounds 70740, OS waits 33434
RW-excl spins 0, rounds 94359, OS waits 4228
RW-sx spins 2111, rounds 55933, OS waits 1523
Spin rounds per wait: 70740.00 RW-shared, 94359.00 RW-excl, 26.50 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 1213126
Purge done for trx's n:o < 1213126 undo n:o < 0 state: running but idle
History list length 3
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422148390082168, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 422148390081352, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
124952 OS file reads, 245278 OS file writes, 82495 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 24.28 writes/s, 8.28 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 63, seg size 65, 70 merges
merged operations:
 insert 37, delete mark 607, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 1593833, node heap has 1953 buffer(s)
Hash table size 1593833, node heap has 178 buffer(s)
Hash table size 1593833, node heap has 97 buffer(s)
Hash table size 1593833, node heap has 2315 buffer(s)
Hash table size 1593833, node heap has 128 buffer(s)
Hash table size 1593833, node heap has 135 buffer(s)
Hash table size 1593833, node heap has 35 buffer(s)
Hash table size 1593833, node heap has 39 buffer(s)
765.60 hash searches/s, 525.21 non-hash searches/s
---
LOG
---
Log sequence number 12869849455
Log flushed up to   12869849455
Pages flushed up to 12869849455
Last checkpoint at  12869849331
0 pending log flushes, 0 pending chkp writes
53483 log i/o's done, 3.71 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 6627000320
Dictionary memory allocated 3675472
Buffer pool size   393216
Free buffers       262869
Database pages     125467
Old database pages 46429
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 24, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 124488, created 979, written 162905
0.00 reads/s, 0.00 creates/s, 18.28 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 125467, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   65536
Free buffers       43142
Database pages     21580
Old database pages 7985
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 21405, created 175, written 28103
0.00 reads/s, 0.00 creates/s, 5.57 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 21580, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   65536
Free buffers       43698
Database pages     21029
Old database pages 7782
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 20714, created 315, written 20255
0.00 reads/s, 0.00 creates/s, 6.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 21029, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   65536
Free buffers       43979
Database pages     20742
Old database pages 7676
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 10, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 20617, created 125, written 35035
0.00 reads/s, 0.00 creates/s, 4.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 20742, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   65536
Free buffers       43611
Database pages     21117
Old database pages 7815
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 20991, created 126, written 30631
0.00 reads/s, 0.00 creates/s, 1.71 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 21117, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   65536
Free buffers       44135
Database pages     20585
Old database pages 7618
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 20469, created 116, written 30474
0.00 reads/s, 0.00 creates/s, 0.71 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 20585, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   65536
Free buffers       44304
Database pages     20414
Old database pages 7553
Modified db pages  0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 7, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 20292, created 122, written 18407
0.00 reads/s, 0.00 creates/s, 0.29 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 20414, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=7731, Main thread ID=140666264016640, state: sleeping
Number of rows inserted 8611, updated 31931, deleted 19012, read 210937170
0.43 inserts/s, 1.86 updates/s, 0.00 deletes/s, 2021.00 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Best Answer

If the top output you included is typical, your problem has nothing to do with MySQL.

%Cpu(s): 15.5 us,  5.7 sy,  0.0 ni, 38.3 id,  1.2 wa,  0.0 hi,  0.5 si, 38.8 st
                                                                        ^^^^^^^

Notice that last bit I've highlighted? "st" stands for "steal time". 38.8% of your CPU time is unavailable due to other virtual machines or processes running on the host machine.

If your virtual machine is in a public cloud, contact your hosting provider, and consider moving to another host if the problem continues.

If your virtual machine is hosted on site, you have oversubscribed your VM host. Add more physical hosts, or reduce CPU load on other virtual machines.

Related Solutions

Amazon EBS – Investigating High Write Volume on Root Volume

Since the leading cause seemed to be journaling, that would have been my next step. In order to remove journaling, however, I would need to attach the EBS volume to another instance. I decided to test the procedure out using a (day old) snapshot, however, before removing journaling, I re-ran the 10 minute iotop test (on the test instance). To my surprise, I saw normal (i.e. non-elevated) values, and this was the first time that flush-202 didn't even show up on the list. This was a fully functional instance (I restored snapshots of my data as well) - there had been no changes to the root volume in the 12 hours or so since it was taken. All tests showed that the same processes were running on both servers. This led me to believe that the cause must come down to some requests that the 'live' server is processing.

Looking at the differences between the iotop outputs of the server displaying the problem and the seemingly identical server that had no problem, the only differences were flush-202 and php-fpm. This got me thinking that, while a long shot, perhaps it was a problem related to the PHP configuration.

Now, this part wasn't ideal - but since none of the services running on the live server would suffer from a few minutes of downtime it didn't really matter. To narrow down the problem, all the major services (postfix, dovecot, imapproxy, nginx, php-fpm, varnish, mysqld, varnishncsa) on the live server were stopped, and the iotop test rerun - there was no elevated disk i/o. The services were restarted in 3 batches, leaving php-fpm until the end. After each batch of restarts, the iotop test confirmed that there was no issue. Once php-fpm was started the issue returned. (It would have been easy enough to simulate a few PHP requests on the test server, but at this point, I wasn't sure it was actually PHP).

Unfortunately, the server would be rather pointless without PHP, so this wasn't an ideal conclusion. However, since flush-202 seemed to suggest something relating to memory (despite having ample free memory), I decided to disable APC. Rerunning the iotop test showed that disk i/o levels were normal. A closer look into the matter showed that mmap was enabled, and that apc.mmap_file_mask was set to /tmp/apc.XXXXXX (the default for this install). That path sets APC to use file-backed mmap. Simply commenting this line out (therefore using the default - anonymous memory backed) and rerunning the iotop test showed the problem was resolved.

I still do not know why none of the diagnostics run did not identify the writes as coming from php and going to the apc files in the /tmp directory. The only test that even mentioned the /tmp directory was lsof, however, the files it listed were non-existent.

MariaDB 10.3 High CPU Usage – Server Performance Tips

Suggestions to consider for your my.cnf OR my.ini [mysqld] section (RPS = Rate Per Second)

# 20180901 1346 from mysqlservertuning.com
# log_error=/var/lib/mysql/2cd908c24352-error.log  # from default of stderr, for log
# max_connect_errors=10  # from 1000000 - why give a cracker/hacker more than 10 shots?
# tmp_table_size=320M  # from 1G to stay under 1% RAM
# max_heap_table_size=320M  # from 1G should be same as TTS
# thread_cache_size=100  # from 128 for CAP suggested in V8 refman to avoid OOM
# innodb_io_capacity=15000  # from 200 to allow more IOPS for your SSD
# read_buffer_size=256K  # from 128K to reduce handler_read_next RPS
# read_rnd_buffer_size=128K  # from 256K to reduce handler_read_rnd_next RPS
# key_cache_age_threshold=3600  # from 300 seconds to delay AGE OUT and reduce key_reads RPS
# innodb_buffer_pool_instances=1  # from 8 to minimize impact of innodb_lru_scan_depth on CPU every second
# thread_concurrency=14  # from 10 to encourage multi processing when possible with your 8 cores
# min_examined_row_limit=1  # from 0 to reduce slow query log clutter

Each DAY, save your current my.cnf OR my.ini in \history with DATED timed filename such as 20180827hhmm-my.cnf to allow going back to last working my.cnf OR my.ini quickly.

Copy this BLOCK (including the leading date and our web site name)to END of your [mysqld] section and ENABLE ONE change per DAY by removing leading # and spacecharacter, monitor before moving on to next change.

Disable EARLIER same NAMED variable with leading # and space bar, to avoid confusion. In 5 years you will still have history of my.cnf OR my.ini changes with approximate dates.

Normally only ONE change per day, monitor before moving to next change. If a change seems detrimental, go back to last working my.cnf OR my.ini and let us know, please.

Best Answer

Related Solutions

Amazon EBS – Investigating High Write Volume on Root Volume

MariaDB 10.3 High CPU Usage – Server Performance Tips

Related Topic