We have an hard-to-understand issue with our production MySQL RDS 8.0.20 instance. It's db.r5.2xlarge instance, Ireland region, Multi-AZ, besides, there is a Replica.
Every hour, at the exact same time, at :00 we experience a database glitch. Sometimes it's big and customers are affected, sometimes it's not, but we always see a glitch.
By big I mean it could be few seconds or even up to 10 seconds, by small I mean it could be second or so. What is a glitch? Well, our java application fires the following sequences:
- set autocommit = 0
- Then makes insert(s) / update(s) / select(s)
So what we see, is that this exact COMMIT sql takes lots of time. Literally, in our slow query logs, we see 10s or 20s COMMITs. To put it simply: selects, inserts, updates go fast, COMMITs are stuck. Once an hour, at :00.
In performance insights, we see that there is a spike, every hour, at the exact time of a glitch. wait/sync/cond/sql/MYSQL_BIN_LOG::COND_done contributes to this spike. The queries are in status "waiting for handler commit".
There is an increased database connections at this time, but this is normal & expected: if application continues to receive http requests and some database connections from the conn. pool are stucked, then application starts to open new connections.
We noticed that there is a minor spike in Write Latency ( it's visible in RDS console ). It's usually 3ms, but it jumps to 8ms. We suspect that it may have a big/huge value during the glitch, but it's 8ms because it's averaged for a minute. Unfortunately, the minute of granularity seems the maximum.
We haven't noticed any other change of metrics. Disk IO, CPU, innodb reads / writes / updates look good, both from normal monitoring and from the performance insights look good. We haven't even noticed anything in Enhanced monitoring. Write IOPS is 600, Read IOPS is 300, Queue Depth is 0.75. They sometimes jumping due to the heavy read SQLs, but they are very stable +- during the glitch.
We don't see anything unusual in innodb_rows_read.avg, innodb_rows_updated.avg, innodb_rows_deleted.avg and innodb_rows_inserted.avg. Basically, during the time of a glitch, +- 2 minutes these metrics are usual, which means that there is no any special activity going during this time.
We have also reviewed all our cron jobs etc, it doesn't look to us that there is anything happening in the database which contributes to this glitch. There are increased locks at this time, but I think it's also expected: queries are waiting for lock on binlog.
We have innodb_flush_log_at_trx_commit = 2 and sync_binlog = 0. We have innodb_log_file_size = 134217728, which is 134 MB. I know, it's a bit small and could be made 1GB, but since the issue happens at exact time without any insert / update / delete activity, I doubt it's connected.
There are no other slow query logs ( > 1s ) at the time or before the time.
A bit of data from SHOW ENGINE INNODB STATUS ( run at normal time when there is no issue but a good production load ):
7174379566 OS file reads, 10959861316 OS file writes, 1045626171 OS fsyncs 215.88 reads/s, 16384 avg bytes/read, 1249.28 writes/s, 128.21 fsyncs/s 482.54 inserts/s, 210.98 updates/s, 48.02 deletes/s, 56656.29 reads/s Number of system rows inserted 10524, updated 61130, deleted 6743, read 66988909 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 17.58 reads/s
Upd on 13.04
Dears, thank you for helping, attaching more info for visibility and also some more research results.
We were suggested that innodb_io_capacity could be an issue as the default value 200 is not enough. We have verified and found out that at any arbitrary time ( during peak traffic! ) we have less than 1% of dirty pages. So it's not issue.
We were suggested to disable innodb_change_buffering ( put it to None instead of All ). However, this query taken from MySQL docs suggested that we don't have lots of change_buffer_pages, i.e. change_buffer_page_percentage = 0.28
SELECT (SELECT COUNT() FROM INFORMATION_SCHEMA.INNODB_BUFFER_PAGE WHERE PAGE_TYPE LIKE 'IBUF%') AS change_buffer_pages, (SELECT COUNT() FROM INFORMATION_SCHEMA.INNODB_BUFFER_PAGE) AS total_pages, (SELECT ((change_buffer_pages/total_pages)*100)) AS change_buffer_page_percentage;
We were checking 20 minutes after the glitch, 2 mins before the glitch etc. All the times change_buffer_page_percentage is less than 0.5
AWS claims that other customer can't affect this. We will keep insisting.
It seems that the glitch happens at 00 minute of every hour, somewhere at 30 seconds, i.e. ~hh:00:30. Usually it lasts 1 to few seconds.
Some screens attached for more visibility. Attaching some screens from AWS RDS Enhanced Monitoring with 1 sec resolution ( there is absolutely nothing visible in normal 1 minute resolution ).
Avg Queue Size had a big spike, Disk IO Util jumped to 100%, Disk IO Await had a spike. ( the biggest spikes were around 09:00:40 utc time ) The interesting thing to note that there were no spikes in TPS, Read Kb/s, Write Kb/s, Read IO/s, Write IO/s. Physical Disk IO metrics didn't have any spikes. CPU Total maximum value was around 60, CPU Idle minimum value was around 40.
Upd with SHOW ENGINE INNODB STATUS
At 09:00:16 - before the issue is happening. https://pastebin.com/8Ca6nX1H
At 09:00:31 - the issue is not yet happening ( or maybe, just starting to happen? ). There is no transactions stuck, but SEMAPHORE section looks a bit suspicious, it looks like there is a contention. https://pastebin.com/amK4L789
At 09:00:32 - here we already have an issue. You can clearly see that there are lots of transactions in "commit" state. This is the glitch. https://pastebin.com/NgTUzkqc
At 09:00:35 - we have even more transactions stuck.
P.S I have lots of these "show engine innodb status". Starting from 08:55 ( i.e. 5 mins before the glitch ) and possibly ending 5 minutes after the glitch, I can attach more if needed.
SHOW GLOBAL STATUS at 17:00:08 UTC ( before the glitch ): https://pastebin.com/88qXVuVW
SHOW GLOBAL STATUS at 17:01:08 UTC ( after the glitch ): https://pastebin.com/p2arDzmm
The issue is still happening, we are looking to make restart-required changes on the weekends at night. At this moment, we have changed dynamic configuration for innodb_change_buffering and we disabled it, i.e. set it to none. This was suggestion by AWS. Didn't help.
As most of these parameters require restart, we will apply them during the weekend ( innodb_thread_concurrency is already inifnite ):
innodb_read_io_threads=64 # from 4 to encourage multi core processing innodb_write_io_threads=64 # from 4 part 2 as listed in dba.stackexchange.com Question 5666 innodb_thread_concurrency=0 # to ensure OS managed active threads per Q 5666 Rolando answer innodb_lru_scan_depth=100 # from ? to conserve 90% CPU cycles used for function net_buffer_length=64K # from 16K to reduce packet handling interruptions