MySQL slow log online problems and optimization solutions

MySQL slow log is a type of information that MySQL DBAs and other development and operation personnel need to pay close attention to. Slow logs can be used to identify SQL statements that take a long time to execute or do not follow indexes, providing a basis for system tuning.

This article will use an online case to analyze how to correctly set MySQL slow log parameters and use the slow log function, and introduce the enhancements to the MySQL slow log function by NetEase Cloud RDS.

MySQL parameter group functionality

NetEase Cloud RDS instances provide parameter group management functions. Most commonly used MySQL system parameters can be viewed through the parameter management interface. Users can understand the current operating values ​​and recommended values:

Users can also modify the listed parameters through the parameter management page. Click the "Modify Parameters" button to set them online. Click "Save Changes" to complete the parameter modification of the MySQL master and slave nodes with one click:

It is not difficult to find out from the parameter management interface that there are many parameters related to slow queries. So, how do these parameters work? How are they related to each other? What conditions must be met for SQL statements to be recorded in the slow log? Only by understanding these can we better use slow logs to tune the system and locate problems.

Next, we will use this online case as a reference to introduce how to correctly configure slow log parameters:

Some users reported that the slow logs of multiple RDS 5.7 instances they used were abnormal. SQL statements that took more than a minute to execute were not recorded in the slow logs. SQL statements for reproduction are also provided.

Correct configuration of slow log parameters

First, we need to confirm whether the slow log function is enabled for the instance. By default, the MySQL slow log function is disabled. The slow log switch parameter is slow_query_log, which can be explicitly specified in the mysqld startup command line or configuration file. If slow_query_log=1 is specified or no value is specified, it means that the slow log is turned on, and a value of 0 means it is turned off. Users can dynamically turn it on and off at runtime.

The slow log function is enabled by default for NetEase Cloud RDS instances. We have confirmed that the user did not turn off the slow log switch for the instance.

Next, you need to confirm the slow log record location. MySQL uses the log_output parameter to specify whether to save the slow log in a file (FILE) or a table (TABLE). It should be emphasized that only specifying log_output and setting slow_query_log to 0 will not record slow logs. In other words, slow_query_log is the switch for slow logs. If you use a file to record slow logs, you can specify the file name through slow_query_log_file. If the user does not explicitly specify slow_query_log_file, MySQL will initialize it to host_name-slow.log, where host_name is the host name running mysqld. The slow log file is located in the MySQL data directory by default.

NetEase Cloud RDS instances do not allow users to modify the log file path, but can configure the log_output parameter. By querying, you can confirm that the instance records slow logs in files. Check the log files to confirm that there are no SQL statements as described by the user.

Since the user provided a reproducible statement, we executed the SQL statement and it indeed took more than a minute to return. Through the explain command, we found that it did not go through the index and scanned a large number of records. After checking the slow log again, the SQL statement was still not recorded.

MySQL will record SQL statements that meet the conditions of execution time exceeding long_query_time seconds and number of scanned records exceeding min_examined_row_limit rows.

The minimum and default values ​​of the long_query_time parameter are 1 and 10s respectively. The parameter can be accurate to microseconds (ms). If you choose to record the slow log to a file, the recorded time is accurate to microseconds. If you record it to the slow log table (mysql.slow_log), it is only accurate to seconds and the microsecond part is ignored.

NetEase Cloud RDS instances allow users to set these two parameter values. So did the user adjust the above two thresholds, resulting in failure to meet the recording conditions? Further inquiries revealed that this was not the cause of the problem.

We noticed that MySQL also has a parameter called log_queries_not_using_indexes, which is used to control whether to log SQL queries that do not use indexes. The code is as follows:

Pay special attention to the content indicated by the arrow. If the query does not go through the index or the index is invalid, and the relevant parameters are turned on, then warn_no_index is set to true. If the number of scanned records exceeds the threshold at the same time, it will also be recorded like a slow query. So is this parameter not turned on? The result is still negative.

The cause of the problem

Since there may be many SQL statements that do not use indexes in the database instance, if log_queries_not_using_indexes is enabled, there is a risk of rapid growth of log files or table capacity. In this case, you can set log_throttle_queries_not_using_indexes to limit the number of SQL statements that do not use indexes written to the slow log per minute. The default value of this parameter is 0, which means it is not enabled, that is, the number of SQL statements written is not controlled.

When enabled, the system will open a 60s window after the first query that does not use the index is executed. During this window, only a maximum of log_throttle_queries_not_using_indexes SQL statements will be recorded. The excess will be suppressed. At the end of the time window, the number of slow queries suppressed in the window and the total time spent on these slow queries will be printed. The next statistical time window is not created immediately, but is opened after the next query that does not use the index is executed.

Corresponding to this online problem, log_throttle_queries_not_using_indexes is set to 10, and the following content is periodically printed in the log file:

This is indeed consistent with the phenomenon described above. The user's slow log should be suppressed and aggregated into 359. We tried to set log_throttle_queries_not_using_indexes to 0 and then executed the corresponding SQL statement. Sure enough, the corresponding SQL statement was recorded in the log file.

This online problem seems to have been located. The system generates too many slow logs that are not indexed, and the set log_throttle_queries_not_using_indexes is too small, resulting in the inability to normally record the slow logs that are not indexed by users. But there is still one puzzle that has not been solved. That is, when log_throttle_queries_not_using_indexes is 0, no more than 10 slow logs are printed per minute, let alone the 359 as prompted by throttle. So when it is set to 10, the SQL statement provided by the user should be recorded in the slow log. Why is it not recorded? What is the reason? In fact, the answer can be found by carefully looking at the code logic of MySQL logs that do not use indexes:

The figure above shows the main logic of recording slow logs. Whether to record logs is controlled by the function log_slow_applicable. A part of this function has been analyzed previously. Let's take a closer look at other related contents of this function, as shown in the red box in the figure below:

Suppress_logging is a decisive variable. Only when it is false, the SQL statement can be recorded. The result is related to log_throttle_queries_not_using_indexes. Let's take a closer look at the implementation of log_throttle_qni.log, as shown below:

Eligible is warn_no_index. The inc_log_count() function returns true when the total number of statements that do not use indexes within 1 minute exceeds log_throttle_queries_not_using_indexes. Only when warn_no_index and inc_log_count() return true, suppress_current is true, and suppress_current is suppress_logging.

By analyzing the above two screenshots, we can answer the previous doubts:

log_throttle_queries_not_using_indexes counts all statements that do not use indexes. Some of these statements are not recorded in the slow log because they do not meet the constraint on the number of scanned records. This is why when this value is 10, there are not 10 records in the slow log file. This is because 8 of the 10 SQL statements were not recorded because the number of scanned records was too small.

This also explains the number 359 in the above figure, which is the total number of SQL statements that do not use the index in this time window. Therefore, log_throttle_queries_not_using_indexes is a critical parameter. Improper setting will result in failure to properly record slow queries that do not use indexes, causing partial failure of the slow log function. Therefore, users should first avoid a large number of SQL statements that do not use indexes as much as possible. They can optimize the statements through the RDS health check function. Secondly, if the above prompts appear in the slow log, the value of log_throttle_queries_not_using_indexes should be increased to further analyze the problem.

InnoSQL slow log function enhancement

Some RDS instance users also asked us why their SQL statement execution time did not exceed the set long_query_time and the index was not used, but it was still recorded in the slow log. Is there a bug? In fact, this is not a bug. It is because the InnoSQL (MySQL open source branch maintained by NetEase) version used by NetEase Cloud RDS has optimized the slow log. In addition to examining the execution time of the SQL statement, it also pays attention to the number of disk pages required for the query. If the number of required pages is too large, it may also have a greater impact on the system load. In order to quantify the statistics, we collected the total number of pages that need to be read by the SQL query and the number of actual IOs performed on these pages, which are recorded as logical_reads and physical_reads respectively. The former includes page requests that hit the InnoDB Buffer Pool and those that miss and require IO.

This function is provided to users by introducing two parameters: slow_query_type and long_query_io. The former can be set to 0/1/2/3. "1" means enabling slow log recording based on execution time, "2" means recording slow log based on the total number of searched pages, and "3" is a combination of "1" and "2". Therefore, in InnoSQL, a SQL query can be recorded in the slow log only if the execution time is long enough or the total number of pages required is large enough. The code snippet is as follows:

The page number threshold is measured by the long_query_io parameter, which can be set dynamically by the user. If the total number of pages m_logical_reads exceeds this value, it will be recorded even if the execution time does not exceed the limit. Correspondingly, new fields are added to the RDS instance slow log table structure and slow log file output content.

The figure above shows the InnoSQL version of the slow_log table structure, where logical_reads and physical_reads are fields added by InnoSQL. Similarly, two fields are added to the output of the slow log file, as shown below:

In addition to the above detailed description, the MySQL slow log module has the following features worth noting:

○ The time recorded in the slow log statistics and slow logs does not include the waiting time required to obtain the lock before the SQL statement starts to execute;

○ MySQL writes SQL statements to the slow log only after they have been executed and all the locks held have been released. Therefore, the order in which SQL statements are recorded in the slow log does not accurately reflect the actual execution order of these SQL statements.

○ Each slow log contains a timestamp. If written to a file, the log_timestamps parameter is used to convert the slow log timestamp to the time in the specified time zone. However, this parameter has no effect on the slow logs in the mysql.slow_log table;

○ You can enable the slow log function of the MySQL slave library by setting log_slow_slave_statements;

○ Table management operations such as ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE can also be recorded to the slow log, which can be enabled by the log_slow_admin_statements option.