We are having serious issues with one of our productions servers. The setup in question is CentOS 7 64-bit server with 16 GB of ram and 250GB SSD (so the setup should be very fast). The LEMP stack is configured with MariaDB 10.1.29. We are having about 20 applications running on this server, each using its own database.
Couple of weeks ago we saw in our status monitor (pinging each application in 5 minute intervals and measuring response time) that 3 applications are performing very slowly from time to time. (Response times from 2s-10s while the average is around ~0.1s). The slow log of MariaDB is full of slow queries (most of them easy insert, select and update queries for session storage) which sometimes take up to 15 seconds, but only from these three applications.
What these three applications have in common compared to the rest, they are all using `InnoDB` instead of `MyISAM`. So for further debugging we converted 3 more applications from MyISAM to InnoDB and these also started to suffer from the same delays.
[![Switch from MyISAM to InnoDB][1]][1]
The problem is (or what makes it hard to debug), we can't see any regularity and queries are working fast in 99% of the cases.
Here is a typical query from slowlog:
# Time: 171127 11:59:37
# User@Host: ci[ci] @ localhost []
# Thread_id: 10299 Schema: ci QC_hit: No
# Query_time: 6.945446 Lock_time: 0.000083 Rows_sent: 0 Rows_examined: 1
# Rows_affected: 1
#
# explain: id select_type table type possible_keys key key_len ref rows r_rows filtered r_filtered Extra
# explain: 1 SIMPLE fx_un_sessions range PRIMARY PRIMARY 386 NULL 1 1.00 100.00 100.00 Using where
#
SET timestamp=1511780377;
UPDATE `fx_un_sessions` SET `timestamp` = 1511780370, `data` = '__ci_last_regenerate|i:1511780354;requested_page|s:30:\"http://ci.test.dev/leads\";user_id|s:1:\"1\";username|s:9:\"admin\";role_id|s:1:\"1\";status|s:1:\"1\";previous_page|s:30:\"http://ci.test.dev/leads\";'
I was able to catch the output of `SHOW ENGINE INNODB STATUS` right after this query...so maybe you can identify the issue:
=====================================
2017-11-27 11:59:37 7fccc41adb00 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 3 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1879 srv_active, 0 srv_shutdown, 69129 srv_idle
srv_master_thread log flush and writes: 71007
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3583
--Thread 140517442575104 has waited at trx0sys.ic line 103 for 7.0000 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7fcca5efd518 '&block->lock'
a writer (thread id 140517442575104) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1113
Last time write locked in file trx0sys.ic line 103
Holder thread 0 file not yet reserved line 0
--Thread 140515701942016 has waited at trx0undo.ic line 191 for 7.0000 seconds the semaphore:
S-lock on RW-latch at 0x7fcca58bfa90 '&block->lock'
a writer (thread id 140517442575104) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0flu.cc line 1113
Last time write locked in file trx0undo.ic line 171
Holder thread 0 file not yet reserved line 0
OS WAIT ARRAY INFO: signal count 3430
Mutex spin waits 5659, rounds 109128, OS waits 1956
RW-shared spins 1487, rounds 44302, OS waits 1466
RW-excl spins 29, rounds 2856, OS waits 87
Spin rounds per wait: 19.28 mutex, 29.79 RW-shared, 98.48 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 13579354
Purge done for trx's n:o < 13579353 undo n:o < 0 state: running
History list length 19
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 10302, OS thread handle 0x7fccc41adb00, query id 390566 localhost pm init
SHOW ENGINE INNODB STATUS
---TRANSACTION 13253635, not started
MySQL thread id 1, OS thread handle 0x7fcccc0efb00, query id 0 Waiting for requests
---TRANSACTION 13579352, ACTIVE 7 sec committing
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 10299, OS thread handle 0x7fccc43fdb00, query id 390535 localhost pm query end
UPDATE `fx_un_sessions` SET `timestamp` = 1511780370, `data` = '__ci_last_regenerate|i:1511780354;requested_page|s:30:\"http://ci.test.dev/leads\";user_id|s:1:\"1\";username|s:9:\"admin\";role_id|s:1:\"1\";status|s:1:\"1\";previous_page|s:30:\"http://ci.test.dev/leads\";'
WHERE `id` = '1sg79p2m7ure6ejk987eu5o5gpjir6p9'
Trx #rec lock waits 0 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC
--------
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 (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (read thread)
I/O thread 9 state: waiting for completed aio requests (read thread)
I/O thread 10 state: waiting for completed aio requests (read thread)
I/O thread 11 state: waiting for completed aio requests (read thread)
I/O thread 12 state: waiting for completed aio requests (read thread)
I/O thread 13 state: waiting for completed aio requests (read thread)
I/O thread 14 state: waiting for completed aio requests (read thread)
I/O thread 15 state: waiting for completed aio requests (read thread)
I/O thread 16 state: waiting for completed aio requests (read thread)
I/O thread 17 state: waiting for completed aio requests (read thread)
I/O thread 18 state: waiting for completed aio requests (read thread)
I/O thread 19 state: waiting for completed aio requests (read thread)
I/O thread 20 state: waiting for completed aio requests (read thread)
I/O thread 21 state: waiting for completed aio requests (read thread)
I/O thread 22 state: waiting for completed aio requests (read thread)
I/O thread 23 state: waiting for completed aio requests (read thread)
I/O thread 24 state: waiting for completed aio requests (read thread)
I/O thread 25 state: waiting for completed aio requests (read thread)
I/O thread 26 state: waiting for completed aio requests (read thread)
I/O thread 27 state: waiting for completed aio requests (read thread)
I/O thread 28 state: waiting for completed aio requests (read thread)
I/O thread 29 state: waiting for completed aio requests (read thread)
I/O thread 30 state: waiting for completed aio requests (read thread)
I/O thread 31 state: waiting for completed aio requests (read thread)
I/O thread 32 state: waiting for completed aio requests (read thread)
I/O thread 33 state: waiting for completed aio requests (read thread)
I/O thread 34 state: waiting for completed aio requests (read thread)
I/O thread 35 state: waiting for completed aio requests (read thread)
I/O thread 36 state: waiting for completed aio requests (read thread)
I/O thread 37 state: waiting for completed aio requests (read thread)
I/O thread 38 state: waiting for completed aio requests (read thread)
I/O thread 39 state: waiting for completed aio requests (read thread)
I/O thread 40 state: waiting for completed aio requests (read thread)
I/O thread 41 state: waiting for completed aio requests (read thread)
I/O thread 42 state: waiting for completed aio requests (read thread)
I/O thread 43 state: waiting for completed aio requests (read thread)
I/O thread 44 state: waiting for completed aio requests (read thread)
I/O thread 45 state: waiting for completed aio requests (read thread)
I/O thread 46 state: waiting for completed aio requests (read thread)
I/O thread 47 state: waiting for completed aio requests (read thread)
I/O thread 48 state: waiting for completed aio requests (read thread)
I/O thread 49 state: waiting for completed aio requests (read thread)
I/O thread 50 state: waiting for completed aio requests (read thread)
I/O thread 51 state: waiting for completed aio requests (read thread)
I/O thread 52 state: waiting for completed aio requests (read thread)
I/O thread 53 state: waiting for completed aio requests (read thread)
I/O thread 54 state: waiting for completed aio requests (read thread)
I/O thread 55 state: waiting for completed aio requests (read thread)
I/O thread 56 state: waiting for completed aio requests (read thread)
I/O thread 57 state: waiting for completed aio requests (read thread)
I/O thread 58 state: waiting for completed aio requests (read thread)
I/O thread 59 state: waiting for completed aio requests (read thread)
I/O thread 60 state: waiting for completed aio requests (read thread)
I/O thread 61 state: waiting for completed aio requests (read thread)
I/O thread 62 state: waiting for completed aio requests (read thread)
I/O thread 63 state: waiting for completed aio requests (read thread)
I/O thread 64 state: waiting for completed aio requests (read thread)
I/O thread 65 state: waiting for completed aio requests (read thread)
I/O thread 66 state: waiting for completed aio requests (write thread)
I/O thread 67 state: waiting for completed aio requests (write thread)
I/O thread 68 state: waiting for completed aio requests (write thread)
I/O thread 69 state: waiting for completed aio requests (write thread)
I/O thread 70 state: waiting for completed aio requests (write thread)
I/O thread 71 state: waiting for completed aio requests (write thread)
I/O thread 72 state: waiting for completed aio requests (write thread)
I/O thread 73 state: waiting for completed aio requests (write thread)
I/O thread 74 state: waiting for completed aio requests (write thread)
I/O thread 75 state: waiting for completed aio requests (write thread)
I/O thread 76 state: waiting for completed aio requests (write thread)
I/O thread 77 state: waiting for completed aio requests (write thread)
I/O thread 78 state: waiting for completed aio requests (write thread)
I/O thread 79 state: waiting for completed aio requests (write thread)
I/O thread 80 state: waiting for completed aio requests (write thread)
I/O thread 81 state: waiting for completed aio requests (write thread)
I/O thread 82 state: waiting for completed aio requests (write thread)
I/O thread 83 state: waiting for completed aio requests (write thread)
I/O thread 84 state: waiting for completed aio requests (write thread)
I/O thread 85 state: waiting for completed aio requests (write thread)
I/O thread 86 state: waiting for completed aio requests (write thread)
I/O thread 87 state: waiting for completed aio requests (write thread)
I/O thread 88 state: waiting for completed aio requests (write thread)
I/O thread 89 state: waiting for completed aio requests (write thread)
I/O thread 90 state: waiting for completed aio requests (write thread)
I/O thread 91 state: waiting for completed aio requests (write thread)
I/O thread 92 state: waiting for completed aio requests (write thread)
I/O thread 93 state: waiting for completed aio requests (write thread)
I/O thread 94 state: waiting for completed aio requests (write thread)
I/O thread 95 state: waiting for completed aio requests (write thread)
I/O thread 96 state: waiting for completed aio requests (write thread)
I/O thread 97 state: waiting for completed aio requests (write thread)
I/O thread 98 state: waiting for completed aio requests (write thread)
I/O thread 99 state: waiting for completed aio requests (write thread)
I/O thread 100 state: waiting for completed aio requests (write thread)
I/O thread 101 state: waiting for completed aio requests (write thread)
I/O thread 102 state: waiting for completed aio requests (write thread)
I/O thread 103 state: waiting for completed aio requests (write thread)
I/O thread 104 state: waiting for completed aio requests (write thread)
I/O thread 105 state: waiting for completed aio requests (write thread)
I/O thread 106 state: waiting for completed aio requests (write thread)
I/O thread 107 state: waiting for completed aio requests (write thread)
I/O thread 108 state: waiting for completed aio requests (write thread)
I/O thread 109 state: waiting for completed aio requests (write thread)
I/O thread 110 state: waiting for completed aio requests (write thread)
I/O thread 111 state: waiting for completed aio requests (write thread)
I/O thread 112 state: waiting for completed aio requests (write thread)
I/O thread 113 state: waiting for completed aio requests (write thread)
I/O thread 114 state: waiting for completed aio requests (write thread)
I/O thread 115 state: waiting for completed aio requests (write thread)
I/O thread 116 state: waiting for completed aio requests (write thread)
I/O thread 117 state: waiting for completed aio requests (write thread)
I/O thread 118 state: waiting for completed aio requests (write thread)
I/O thread 119 state: waiting for completed aio requests (write thread)
I/O thread 120 state: waiting for completed aio requests (write thread)
I/O thread 121 state: waiting for completed aio requests (write thread)
I/O thread 122 state: waiting for completed aio requests (write thread)
I/O thread 123 state: waiting for completed aio requests (write thread)
I/O thread 124 state: waiting for completed aio requests (write thread)
I/O thread 125 state: waiting for completed aio requests (write thread)
I/O thread 126 state: waiting for completed aio requests (write thread)
I/O thread 127 state: waiting for completed aio requests (write thread)
I/O thread 128 state: waiting for completed aio requests (write thread)
I/O thread 129 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 1; buffer pool: 0
9448 OS file reads, 19554 OS file writes, 8683 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 17 merges
merged operations:
insert 18, delete mark 0, delete 0
discarded operations:
insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 640945853
Log flushed up to 640942303
Pages flushed up to 640940676
Last checkpoint at 640931678
Max checkpoint age 38358836
Checkpoint age target 37160123
Modified age 5177
Checkpoint age 14175
1 pending log writes, 0 pending chkp writes
3485 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 203177984; in additional pool allocated 0
Total memory allocated by read views 288
Internal hash tables (constant factor + variable factor)
Adaptive hash index 4124640 (3071864 + 1052776)
Page hash 192776 (buffer pool 0 only)
Dictionary cache 14775380 (769456 + 14005924)
File system 1921264 (812272 + 1108992)
Lock system 481792 (480712 + 1080)
Recovery system 0 (0 + 0)
Dictionary memory allocated 14005924
Buffer pool size 11839
Buffer pool size, bytes 193970176
Free buffers 3412
Database pages 8363
Old database pages 3106
Modified db pages 17
Percent of dirty pages(LRU & free pages): 0.144
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 2, single page 0
Pages made young 6, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 8223, created 140, written 14482
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8363, 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
1 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
1 out of 1000 descriptors used
Main thread process no. 23228, id 140515735500544, state: flushing log
Number of rows inserted 1918, updated 912, deleted 2072, read 5537548
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 2
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
Here are the InnoDB related settings of my `server.cnf`
innodb_buffer_pool_instances = 1
innodb_log_file_size = 16M
innodb_buffer_pool_size = 185M
innodb_io_capacity = 2000
innodb_read_io_threads = 64
innodb_thread_concurrency = 0
innodb_write_io_threads = 64
innodb_flush_log_at_trx_commit = 0
innodb_log_file_size = 23M
Do you have any ideas what the problem might be or how I can further debug the issue? I am kind of lost.
[1]: https://i.sstatic.net/jBd7X.png