I am currently doing some stress testing where I am pushing inserts to the database as fast as I can. The simulation inserts 10000 records per second. After inserting around 200 million records I found that the inserts were very slow. So I stopped the simulation.

Currently I have stopped pushing any transactions to the database. As such there are no inserts, updates. There have been no deletes to this database in this entire simulation. Yet there are so many IO operations to the disk going on.

When I check the innodb status and iostat, i can see that the Mysql Innodb engine is busy doing disk operations. I am not able to figure out the reason for these IO.

The IO rate is pretty high and as such its causing a bottleneck to push further requests to the Database.

Any help is appreciated. I have attached the InnodB engine status.

my.cnf configuration:

| InnoDB |      | 
2014-08-26 00:02:50 7fc41d38f700 INNODB MONITOR OUTPUT
Per second averages calculated from the last 28 seconds
srv_master_thread loops: 16554 srv_active, 0 srv_shutdown, 6695 srv_idle
srv_master_thread log flush and writes: 23248
OS WAIT ARRAY INFO: reservation count 74717
--Thread 140480424269568 has waited at btr0cur.cc line 545 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7fc5ecdc7af8 created in file dict0dict.cc line 2505
a writer (thread id 140480399091456) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: fffffffffff00000
Last time read locked in file btr0cur.cc line 545
Last time write locked in file /build/buildd/mysql-5.6-5.6.19/storage/innobase/ibuf/ibuf0ibuf.cc line 409
OS WAIT ARRAY INFO: signal count 72822
Mutex spin waits 234298, rounds 1620740, OS waits 42193
RW-shared spins 9405, rounds 170212, OS waits 5011
RW-excl spins 23541, rounds 884561, OS waits 26158
Spin rounds per wait: 6.92 mutex, 18.10 RW-shared, 37.58 RW-excl
Trx id counter 5263484
Purge done for trx's n:o < 5198325 undo n:o < 0 state: running but idle
History list length 604
---TRANSACTION 0, not started
MySQL thread id 76, OS thread handle 0x7fc41d38f700, query id 1482925 localhost ddosprofile init
show engine innodb status
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: complete io for buf page (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: complete io for buf page (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: 22 [3, 2, 8, 9] , 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: 2
25561 OS file reads, 10271392 OS file writes, 138838 OS fsyncs
0 pending preads, 1 pending pwrites
23.57 reads/s, 16384 avg bytes/read, 263.95 writes/s, 8.36 fsyncs/s
Ibuf: size 562, free list len 24162, seg size 24725, 18712 merges
merged operations:
 insert 169928, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 12749951, node heap has 3 buffer(s)
0.00 hash searches/s, 113.57 non-hash searches/s
Log sequence number 183651147315
Log flushed up to   183651127940
Pages flushed up to 183242751536
Last checkpoint at  183241671211
0 pending log writes, 0 pending chkp writes
98244 log i/o's done, 0.54 log i/o's/second
Total memory allocated 6593445888; in additional pool allocated 0
Dictionary memory allocated 87500
Buffer pool size   393215
Free buffers       1
Database pages     393211
Old database pages 145154
Modified db pages  178594
Pending reads 25
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 15953492, not young 42560
0.00 youngs/s, 0.00 non-youngs/s
Pages read 25519, created 1321453, written 10147162
22.71 reads/s, 0.00 creates/s, 263.45 writes/s
Buffer pool hit rate 969 / 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: 393211, unzip_LRU len: 0
I/O sum[11937]:cur[103], unzip sum[0]:cur[0]
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 8090, id 140480331949824, state: doing insert buffer merge
Number of rows inserted 196205997, updated 0, deleted 972, read 1134
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

That is 100% normal: what you are seeing is the background threads performing the following operations:

  • Flushing dirty pages from the buffer pool into the tablespace files. You can see that is happening on your case due to the difference between your LSN and the latest checkpoint on the SHOW ENGINE INNODB STATUS.
  • Merging non-unique secondary indexes modifications from the change buffer (inside the buffer pool) into disk. It is almost empty now, but it did 169928 merge inserts since the server started.
  • Purging deleted rows so that free space inside the tablespace can be retrieved. Your history lenght is now 604, so it may not be executing right now.
  • As a less intensive operation, preloading pages from disk into the buffer pool. There are 22 of those pending, and some of them are being done right now.
  • Additionally, if you cancelled an on-going transaction, a thread may be rollbacking those results, and depending on the size of the transaction, it can take very long. Not happening right now, this is a foreground operation.

The first four are background threads to allow better performance on multi-cores systems and its usage kicks in with more intensity during the server idle time, so it is normal that you observe extra IO after stopping a rather intensive benchmark. Normally you should not worry about them. You can monitor them on SHOW ENGINE INNODB STATUS, they do not compromise the durability of your statements (if you were using innodb_flush_log_at_trx_commit = 1, once everything is committed, nothing is lost) and you can reduce its activity at the cost of worse performance:

  • innodb_max_dirty_pages_pct can be reduced for more "syncronous I/O". Many other changes can be changed about the flushing policy.
  • the purge threads can be reduced and configured to kick in more frequently
  • the change buffer can be disabled
  • the buffer readers can be configured so it does not load so many pages

None of this changes are recommended unless they are a problem or you have very fast I/O like flash cards/SSDs.

The last point mentioned (rollbacks) is as easy to fix as: don't do them if you have large transactions (or just do not do large transactions if you can suffer rollbacks). The rollback operations is way more costly than a commit.

So your problem is probably in other place. If you are just testing, you can just kill your server and generate a new installation.

There are some comments that I would do on the shown configuration, but I can't do reliably without seeing your hardware and knowing what your test load was. I am just achieving 200.000 inserts/s on 5.6.20, but on tables <100,000,000 rows and doing some dirty tricks. InnoDB tends to be worse the larger the table is, please consider partitioning or a larger buffer pool (it is 100% full here).

  • Thank you very much. I just started on Mysql a month ago and have loads to learn. Your help is appreciated. Thank you so much. – Laxman Prabhu Aug 26 '14 at 18:43

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.