InnoDB Mariadb 10.0.27 high IO while idle

innodbmariadb

centos7

mariadb 10.0.27

Yesterday i did a lot of delete operations from innodb tables (table size – 100gb, deleted part – 40gb. Many indexes on table).

And now i have strange situation on this server.

Up for 8 hours there is one read thread and one write thread (seems like its a purge thread's):

2455 be/4 mysql 2.40 M/s 0.00 B/s 0.00 % 97.34 % mysqld --basedir=/usr --datadir=/var/lib/mysql 
2457 be/4 mysql 0.00 B/s 5.81 M/s 0.00 % 1.34 % mysqld --basedir=/usr --datadir=/var/lib/mysql

No queries are running on the server. General_log is empty. show full processlist is empty. INNODB_TRX table is empty.

Usually i can stop my mysql server in two second. Now he stops in 2-5 minutes. Seems like problem in purge threads:

190801 12:02:48 [Note] /usr/sbin/mysqld: Normal shutdown
190801 12:02:48 [Note] Event Scheduler: Purging the queue. 2 events
190801 12:02:48 [Note] InnoDB: FTS optimize thread exiting.
190801 12:02:48 [Note] InnoDB: Starting shutdown...
190801 12:03:48 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:04:48 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:05:48 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:06:49 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:07:49 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:08:49 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:09:49 [Note] InnoDB: Waiting for purge thread to be suspended
190801 12:10:48 [Note] InnoDB: Shutdown completed; log sequence number 2158074213872
190801 12:10:48 [Note] /usr/sbin/mysqld: Shutdown complete

After a reboot, purge thread continue to give high IO load on disk.

Also i can see a lot of read/write operation in buffer pools:

BACKGROUND THREAD
-----------------
srv_master_thread loops: 1545 srv_active, 0 srv_shutdown, 3791 srv_idle
srv_master_thread log flush and writes: 5336

TRANSACTIONS
------------
Trx id counter 22228107
Purge done for trx's n:o < 22202871 undo n:o < 469 state: running
History list length 1282
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 22228106, not started
MySQL thread id 158, OS thread handle 0x7f41ed50e700, query id 129930 10.15.20.188 admin init
SHOW ENGINE INNODB STATUS

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, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
760441 OS file reads, 1081085 OS file writes, 66030 OS fsyncs
1 pending preads, 0 pending pwrites
99.14 reads/s, 16384 avg bytes/read, 260.67 writes/s, 15.50 fsyncs/s

LOG
---
Log sequence number 2151663951156
Log flushed up to 2151663911289
Pages flushed up to 2151597015337
Last checkpoint at 2151596987934
Max checkpoint age 433210615
Checkpoint age target 419672784
Modified age 66935819
Checkpoint age 66963222
0 pending log writes, 0 pending chkp writes
16181 log i/o's done, 2.41 log i/o's/second

ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
0 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
0 out of 1000 descriptors used
Main thread process no. 2434, id 139921331304192, state: sleeping
Number of rows inserted 3954, updated 0, deleted 0, read 40510374
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.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

----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 3353346048; in additional pool allocated 0
Total memory allocated by read views 264
Internal hash tables (constant factor + variable factor)
Adaptive hash index 57408560 (50998216 + 6410344)
Page hash 399352 (buffer pool 0 only)
Dictionary cache 12871103 (12750992 + 120111)
File system 952552 (812272 + 140280)
Lock system 7970576 (7969496 + 1080)
Recovery system 0 (0 + 0)
Dictionary memory allocated 120111
Buffer pool size 196600
Buffer pool size, bytes 3221094400
Free buffers 127272
Database pages 68937
Old database pages 25601
Modified db pages 8023
Percent of dirty pages(LRU & free pages): 4.089
Max dirty pages percent: 75.000
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 204, not young 0
0.38 youngs/s, 0.00 non-youngs/s
Pages read 68936, created 0, written 128020
100.67 reads/s, 0.00 creates/s, 200.24 writes/s
Buffer pool hit rate 979 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 1.73/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 68937, unzip_LRU len: 0
I/O sum[0]:cur[2328], unzip sum[0]:cur[0]


Config file:
character-set-server = utf8
default-storage-engine = innodb
key_buffer = 128M
innodb_file_per_table = 1
innodb_open_files = 1024
innodb_buffer_pool_size = 3072M
innodb_buffer_pool_instances = 3 #Changed 2 hours ago. Was default (8).
innodb_flush_method=O_DIRECT
innodb_additional_mem_pool_size = 32M
innodb_support_xa = 0
innodb_thread_concurrency = 16
innodb_log_file_size = 256M
innodb_log_buffer_size = 32M
innodb_flush_log_at_trx_commit = 1
innodb_autoextend_increment = 16M
innodb_data_file_path=ibdata1:128M;ibdata2:128M:autoextend
innodb_lock_wait_timeout = 60
max_connections = 150
query_cache_type = 1
query_cache_size = 64M
sort_buffer_size = 16M
join_buffer_size = 16M
table_cache = 256
max_allowed_packet = 16M
open_files_limit = 3000
read_rnd_buffer_size = 4M

InnoDB cannot purge changes on disk? Or its something like B-TREE balancing after delete operation?

Can somebody explain me what going on, please? How to fix it and how avoid such problems in future?

Thank you.

Best Answer

Let it go to completion!

InnoDB does a lot of things to speed up execution. One of them is to delay DELETEs via the Change Buffer (research that). It essentially writes changes (inserts, updates, deletes) to the Change Buffer, then eventually gathers those changes (in a more I/O efficient way!) together to write to disk. The effect is two-fold:

Your DELETE finishes much faster. That is, you get control back from the DELETE query must sooner.
Less I/O needs to be done.

Meanwhile, the rows are DELETEd as far as any query can tell. It is just that not all the work has finished yet.

Tuning tips

innodb_buffer_pool_size should be about 70% of available RAM.

Alternatives

When you need to delete "most" of a table, it is faster (in all respects) to copy over what you want to keep. Something like this:

CREATE TABLE new LIKE real;
INSERT INTO new
    SELECT * FROM real WHERE NOT (delete-expression);
RENAME TABLE real TO old,
             new TO real;
DROP TABLE old;

More big-delete tips

Related Solutions

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

The two answers given from @RickJames and @drogart are essentially the remedies. (+1 for each).

Right from the error log you present, the last two lines say:

InnoDB: Error: log file ./ib_logfile0 is of different size 0 134217728 bytes

InnoDB: than specified in the .cnf file 0 268435456 bytes! `

At that point, it was evident that you set innodb_log_file_size to 256M (268435456) in my.cnf while the InnoDB Transaction Logs (ib_logfile0,ib_logfile1) were respectively 128M (134217728) each. Looking back at the link to my StackOverflow answer in your question, you had to do the following:

Step 01) Add this to my.cnf:

[mysqld]
innodb_buffer_pool_size=4G
innodb_log_file_size=1G

Step 02) Run these command in the OS

mysql -u... -p... -e"SET GLOBAL innodb_fast_shutdown = 1"
service mysql stop
rm -f /var/lib/mysql/ib_logfile*
service mysql start

So as to have confidence in what is happening, run tail -f against the error log. You will see message telling you when each innodb log file is being created.

Mysql – What causes InnoDB to write 100% more pages while slowing down answering queries

The symptoms I've describe are matching with dirty-page-flushing issues in my InnoDB Buffer pool. Dirty pages get flushed from the InnoDB Buffer Pool, among other situations, when InnoDB recycles one of it's Journal Files. This cause en-mass flushing of Data Pages to the disk, which causes I/O Bursts.

The links below suggest some insight on the problem.

http://www.mysqlperformanceblog.com/2008/11/13/adaptive-checkpointing/ http://dimitrik.free.fr/blog/archives/07-01-2010_07-31-2010.html http://www.chriscalender.com/?p=201

The solution passes through choosing either:

Increase the number of the InnoDB Log Files in use, in order to increase the Maximum Checkpoint Age available;
Change the Checkpointing strategy (variable innodb_adaptive_checkpoint) to a more aggressive strategy;
Tuning innodb_io_capacity and the size of InnoDB Log File and Buffer sizes.

Best Answer

Related Solutions

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

Mysql – What causes InnoDB to write 100% more pages while slowing down answering queries

Related Question