MySQL freezes every hour at the exact same time [closed]

Question

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.

Problem:

• 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:

1. set autocommit = 0
2. Then makes insert(s) / update(s) / select(s)
3. commit

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.

Observations:

• 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.

1. 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.

2. 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

3. AWS claims that other customer can't affect this. We will keep insisting.

4. 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.

5. 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 again.

Attaching more screens from Performance Insights. Glitch at 15:00:30.

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

Upd 15.04

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

Answer 1

This is on rds. Probably shared Infra structure. The problem might be a busy neighbor.

An other application that shares your infra might have an hourly procedure that steals your io causing your app a delay.

Answer 2

At exactly :00, do SHOW FULL PROCESSLIST;. You might prep for it by connecting as root just before the top of the hour.

Once you have the list of queries running, provide them, plus SHOW CREATE TABLE for the tables in question.

It sounds like you have a cron job or an EVENT that is being naughty and needs to be improved.

Some common causes:

• Using MyISAM instead of InnoDB.
• Rebuilding a summary table from scratch instead of doing it incrementally.
• Assigning top-of-hour to lots of cron jobs. It is possible, even wise, to scatter them across the hour. Specify different minutes instead of simply 0.

Multiple COMMITs? Are they from different connections? Or explicit COMMITs after each query? Find the queries in the source code. A COMMIT may take a "long time" because of some cleanup work that happens then.

Is Replication / Clustering involved? If so, other causes come to mind.

Set long_query_time = 0.1 across one top-of-hour. That may help find more stuff via the slowlog.

Was a deadlock listed in the SHOW ENGINE InnoDB STATUS? It is usually worth looking into, even if it is unrelated to the target problem.

If you provide GLOBAL STATUS and VARIABLES, something may show up: http://mysql.rjweb.org/doc.php/mysql_analysis#tuning

Answer 3

Summary from SHOW GLOBAL STATUS reports on 4/13/2021 at 17:00 and 17:01 consider these AWS RDS Parameter Group changes,

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

Other observations, SHOW GLOBAL STATUS reports com_begin count did not increase in this one minute com_commit count increased by 128838 - usually these numbers closer to paired com_stmt_prepare count usually is close to com_stmt_close at 151 days almost half have not closed to release resources. SHOW ENGINE INNODB STATUS report includes 'not gap waiting' for a specific table - OPTIMIZE TABLE tbl_name may avoid this issue for this one table.

Providing additional requested Apr 8, 2021 at 21:02 would allow more in depth analysis of your instance performance. One set of SHOW GLOBAL VARIABLES; would be MOST helpful and 400 lines of slow query log from first minute of any hour would be useful.

Answer 4

Originally self-answered in the question body:

---

The problem was in the Secondary Disk, i.e. Multi-AZ.

Solution was to switch off Multi-AZ and then enable again.

This changed the Secondary Disk, actual hardware and the problem disappeared.

To my regret, AWS Support failed to identify the problem.

MySQL internal team even sent a response something like: it's in your application, work with your DBA. Quite a BAD job from their side.