mysqlamazon-web-servicesperformanceamazon-rdsmysql-slow-query-log

Amazon RDS - Slow queries at every minute change


We recently noticed that we have a lot more records in our slow query log at every minute change (at around second 0 of every minute). This didn't seem to be related to any of our cronjobs so I decided to do a quick test on a new RDS t3.micro instance with MySQL 8.0.23.

Here are the steps to replicate:

  1. Create a table:

     CREATE TABLE `_test` (
       `date` datetime NOT NULL,
       `val` int NOT NULL DEFAULT '1'
     ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
     COMMIT;
    
  2. Make 100'000 inserts (important: use a single query for each row, do not insert multiple rows with one query), like:

     INSERT INTO `_test` (`date`, `val`) VALUES (NOW(), '1');
     INSERT INTO `_test` (`date`, `val`) VALUES (NOW(), '1');
     INSERT INTO `_test` (`date`, `val`) VALUES (NOW(), '1');
     ...
    
  3. Run the following query:

     SELECT  SUBSTRING(`date`, -2, 2) AS `second`, AVG(`count`) AS `avg`
       FROM  
         ( SELECT  `date`, COUNT(1) AS `count`
             FROM  `_test`
             GROUP BY  `date`
         ) AS `temp`
       GROUP BY  `second`
       ORDER BY  `avg` ASC
    

My results were:

second avg
00 20.1935
34 50.9667
01 51.1613
26 52.6667
02 52.9032
50 53.5333
20 53.6667
59 53.7188
30 53.8333
06 54.1613
36 54.1667
27 54.3333
05 54.5161
52 54.7742
04 55.0968
35 55.7000
15 55.9000
07 56.0000
38 56.0000
19 56.1000
49 56.1333
11 56.1333
29 56.1667
45 56.2000
03 56.2258

The inserts usually took about 0.02 seconds (50-56 inserts per second on average), except for second 0, where the inserts took 0.05 seconds (only 20 inserts per second on average).

And the lag seems to get bigger with bigger and more complex tables and/or queries with joins. Any idea what may be causing this lag at second 0?

EDIT:

Additional information for @Rick James.

    CREATE TABLE `rds_history` (
     `action_timestamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
     `called_by_user` varchar(50) NOT NULL,
     `action` varchar(20) NOT NULL,
     `mysql_version` varchar(50) NOT NULL,
     `master_host` varchar(255) DEFAULT NULL,
     `master_port` int DEFAULT NULL,
     `master_user` varchar(16) DEFAULT NULL,
     `master_log_file` varchar(50) DEFAULT NULL,
     `master_log_pos` mediumtext,
     `master_ssl` tinyint(1) DEFAULT NULL,
     `master_delay` int DEFAULT NULL,
     `auto_position` tinyint(1) DEFAULT NULL,
     `master_gtid` text
    ) ENGINE=InnoDB DEFAULT CHARSET=latin1

    CREATE TABLE `rds_replication_status` (
     `action_timestamp` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
     `called_by_user` varchar(50) NOT NULL,
     `action` varchar(20) NOT NULL,
     `mysql_version` varchar(50) NOT NULL,
     `master_host` varchar(255) DEFAULT NULL,
     `master_port` int DEFAULT NULL,
     `replication_log_file` text,
     `replication_stop_point` bigint DEFAULT NULL,
     `replication_gtid` text
    ) ENGINE=InnoDB DEFAULT CHARSET=latin1
Name Engine Version Row_format Rows Avg_row_length Data_length Max_data_length Index_length Data_free Auto_increment Create_time Update_time Check_time Collation Checksum Create_options Comment
rds_configuration InnoDB 10 Compact 3 5461 16384 0 0 0 NULL 08.03.21 11:19 NULL NULL latin1_swedish_ci NULL
rds_global_status_history InnoDB 10 Dynamic 0 0 16384 0 0 0 NULL 08.03.21 11:19 NULL NULL latin1_swedish_ci NULL
rds_global_status_history_old InnoDB 10 Dynamic 0 0 16384 0 0 0 NULL 08.03.21 11:19 NULL NULL latin1_swedish_ci NULL
rds_heartbeat2 InnoDB 10 Compact 0 0 16384 0 0 0 NULL 08.03.21 11:19 26.10.21 20:03 NULL latin1_swedish_ci NULL
rds_history InnoDB 10 Dynamic 1 16384 16384 0 0 0 NULL 08.03.21 11:19 NULL NULL latin1_swedish_ci NULL
rds_replication_status InnoDB 10 Dynamic 1 16384 16384 0 0 0 NULL 08.03.21 11:19 NULL NULL latin1_swedish_ci NULL
rds_sysinfo InnoDB 10 Compact 0 0 16384 0 0 0 NULL 08.03.21 11:19 NULL NULL utf8_general_ci NULL

UPDATE:

Just did the same test on a brand new RDS t3.micro instance running MySQL 5.7.34 (default:mysql-5-7 option and parameter group). Similar results:

second avg
00 25.8286
01 44.8857
30 45.0000
22 45.8235
55 46.2857
20 46.8286
15 46.9143
51 47.1143
02 47.3714
45 47.5294
54 47.6286
25 47.6471
50 47.6571
24 47.6765
21 47.7647
10 47.7714
56 47.9714
16 48.1143
43 48.1176
47 48.1429
23 48.2353
07 48.2571
35 48.2647
57 48.3714
53 48.4571
06 48.4857
59 48.5429
05 48.8571
36 49.0588
03 49.1429
46 49.1471
52 49.1714
48 49.1714
26 49.1765
11 49.2000
31 49.2059
40 49.2059
58 49.2286
49 49.2857
39 49.2941
12 49.3429
04 49.3714
19 49.4000
34 49.4118
08 49.4286
38 49.4412
33 49.4706
17 49.5429
09 49.5714
18 49.6286
32 49.6765
27 49.8235
13 49.8286
41 49.8529
29 49.8529
37 49.8824
14 49.8857
44 50.0000
28 50.0588
42 50.0882

Since I wasn't able to replicate the results on my local machine and on a dedicated server (both running MySQL 5.7), this must be an Amazon RDS related problem rather than a MySQL version problem.

I asked Amazon to look into this and do the same test, no response. Their support hasn't been very helpful in general so far. Is anyone else here with an AWS account able to replicate and confirm the results above? I can not believe we are the only ones affected by this.


Solution

  • Since RDS is using block storage (EBS), changes to an RDS database are limited by the IOPS of the storage you choose. General purpose SSD storage comes with 3 IOPS per GB, so you have a limit of 60 IOPS with 20 GB, for example. Now if you use more then the provisioned 60 IOPS, your experiencing a delay at the end of every minute (or the beginning of the new minute).

    Solution: Either increase storage (attention, general purpose SSD [gp2] is limited to a throughput of max 250 MiB/s and, thus, capable of max 1'000 IOPS, even if you increase storage to more than 333 GB) or choose IOPS-SSD storage, which supports higher numbers of IOPS.