MySQL slow log function analysis and optimization enhancements

MySQL slow log (slow log) is a class of information that MySQL DBAs and other developers and operators need to keep an eye on. Use slow logs to find SQL statements, such as long execution times or indexes, to provide a basis for system tuning. This article unifies the online case analysis how to correctly set the MySQL slow log parameter and uses the slow log function, and introduces the NetEase cloud RDS to the MySQL slow log function enhancement.

mysql parameter group feature

NetEase Cloud RDS Instance provides the parameter group management function, through the parameter management interface to view most commonly used MySQL system parameters, the user can understand the current running value and the recommended value, as follows:

The user can also through the parameter Management page to modify the listed parameters, click the "Modify Parameters" button online settings, click "Save Changes" to complete the MySQL master and slave node parameter modification, such as:

Look at the parameter management interface is not difficult to find, and the parameters related to slow query more, how these parameters work, how is the relationship between the conditions of the SQL statement will be recorded in the slow log? Only by understanding these can we make better use of slow logs for system tuning and problem locating. We rely on an online case to describe how to properly configure slow log parameters: users reported that they used multiple RDS 5.7 version instances slow log exception, obviously executed more than a minute of SQL statements, but not recorded in the slow log. SQL statements are also provided for replication.

Slow log parameters configure posture correctly

First, we need to verify that the instance has slow logging turned on, and by default, the MySQL slow log feature is turned off. The slow log switch parameter is Slow_query_log, which can be specified explicitly in the Mysqld startup command line or in the configuration file, or if you specify slow_query_log=1 or do not specify a value, a slow log is turned on, and an assignment of 0 indicates shutdown. Users can turn on and off dynamically at run time. NetEase Cloud RDS instance turns on slow logging by default, and we confirm that the user has not turned off the slow log switch for the instance.

Next, to confirm the slow log record location, MySQL uses the log_output parameter to specify whether to save the slow log as a file or a table (table), you need to emphasize that only specify Log_output and will Slow_query_ Log 0 does not log slow logs , which means that Slow_query_log is the slow log switch. If the slow log is recorded using a file, the file name can be specified by Slow_query_log_file, and if the user does not explicitly specify Slow_query_log_file, then MySQL initializes it to host_name- Slow.log,host_name is the hostname that runs the mysqld, and the slow log file is in the MySQL data directory by default. NetEase Cloud RDS Instance does not allow the user to modify the log file path, but can configure the Log_output parameter, through the query, confirm that the instance records the slow log as a file, and view the log file to confirm that there are no SQL statements as described by the user.

Because the user has provided the replication statement, we executed its SQL statement, indeed 1 minutes to return, through the explain command to find its index, scan a large number of records, again to see the slow log still does not record the SQL statement. MySQL records SQL statements that meet execution times of more than long_query_time seconds and scan records more than Min_examined_row_limit rows . The Long_query_time parameter minimum and default values are 1 and 10s, respectively, and this parameter can be accurate to microseconds (MS). If you choose to log slow logs to a file, the recorded time is accurate to microseconds, and if logged to the slow log table (Mysql.slow_log), then only the seconds are accurate, and the microsecond portion is ignored. NetEase Cloud RDS Instance allows users to set these two parameter values, then is not the user adjusted the above two thresholds, resulting in unable to meet the record conditions, further query discovery is not the cause of the problem.

We notice that MySQL also has a parameter called Log_queries_not_using_indexes that controls whether or not to log an indexed SQL query, with the following code:

Focus on the content of the arrows, if the query does not go index or invalid index, and the relevant parameters are turned on, then the Warn_no_index set to True, if the number of simultaneous scan records to exceed the threshold value, will be as slow as the query is logged, then is not the parameter is not open? The result is still negative.

the cause of the problem

Because there may be more non-indexed SQL statements in the DB instance, if you turn on log_queries_not_using_indexes, there is a risk that the log file or table capacity grows too fast, and you can set Log_throttle_queries_not_ Using_indexes to limit the number of SQL statements that do not go through the index in slow logs per minute, which defaults to 0, which means no control over the number of writes to the SQL statement. When enabled, the system opens a 60s window after the first query that does not go indexed, where only up to log_throttle_queries_not_using_indexes SQL statements are logged. The out-of-section will be suppressed, and at the end of the time window, the number of slow query bars suppressed in the window will be printed and the total time spent on these slow queries. The next Statistical time window is not created immediately, but is opened after the next query that does not follow the index. Corresponding to the problem on this line, Log_throttle_queries_not_using_indexes is set to 10, in the log file to see the following periodic print:

Does conform to the above described phenomenon, the user's slow log should be suppressed, summed up in 359 to go inside. We tried to set Log_throttle_queries_not_using_indexes to 0 and execute the corresponding SQL statement, and the corresponding SQL statement was recorded in the log file. This online problem seems to have been targeted, that is, the system produces too many slow logs, and the set of log_throttle_queries_not_using_indexes is too small, resulting in the inability to properly record the user's slow log index. But there is still a doubt point is not resolved, that is log_throttle_queries_not_using_indexes for 0 o'clock, every minute did not print more than 10 slow logs, and no throttle hint of 359 so much, Then when set to 10, the user-provided SQL statement should be recorded in the slow log to Ah, why there is no record, why? In fact, a closer look at the MySQL record does not go to the index of the log code logic can find the answer:

Is the main logic for logging slow logs, whether the logging is controlled by the function log_slow_applicable, which was previously analyzed as part of the function, we look further at the functions of other related content, see red box:

Suppress_logging is a deterministic variable, and only if it is false, the SQL statement may be logged. The results are related to log_throttle_queries_not_using_indexes, and we take a closer look at Log_throttle_qni.log related implementations, such as:

Eligible that is, the Warn_no_index,inc_log_count () function returns a value of True when the total number of statements that do not go through the index within 1 minutes exceeds log_throttle_queries_not_using_indexes. Only the Warn_no_index and Inc_log_count () return values are true,suppress_current true, and Suppress_current is suppress_logging.

By analyzing the above 2 elements, we can answer the previous question:log_throttle_queries_not_using_indexes counts all statements that do not go through the index, some of which are not recorded in the slow log because they do not meet the constraints of the number of scanned records , which is why there are No 10 records in the slow log file when the value is 10. Because there are 8 SQL statements in these 10 entries because the number of scan records is too small and is not logged.

This also doubts the number of 359, which is the total number of SQL statements that do not go through the index in this time window. Therefore,log_throttle_queries_not_using_indexes is a key parameter, improper setting will not be able to properly record the slow query index, resulting in the slow log function part of the failure.

innosql slow log feature enhancements

There are also some RDS instance users asked us, why my SQL statement execution time does not exceed the set of Long_query_time, and walked the index, but still be recorded in the slow log, is not a bug? In fact, this is not a bug, but because NetEase cloud RDS Use Innosql (NetEase maintenance MySQL Open source Branch) version of the slow log is optimized, in addition to investigating the execution time of the SQL statement, but also focus on the query required disk page number , Because of the excessive number of pages required, it can also have a significant impact on the system load. To be able to quantify statistics, we collected the total number of pages that SQL queries needed to read and the number of actual IO in those pages, recorded as Logical_reads and Physical_reads, including hit InnoDB Buffer. Pool and missed page requests that require IO. This feature is provided to the user by introducing the Slow_query_type and long_query_io two parameters. the former can be set to 0/1/2/3. 1 means that slow logs are recorded based on execution time, 2 means that slow logs are recorded based on the total number of pages searched, and 3 are collections of 1 and 2. So in innosql, SQL queries can be logged to a slow log simply by meeting the execution time or the total number of pages required. The code implementation fragment is as follows:

The page count threshold is measured by the Long_query_io parameter, which can be set dynamically if the total number of pages m_logical_reads exceeds the value, and is recorded even if the execution time is not exceeded. Correspondingly, the RDS instance slow log table structure and the slow log file output also add new fields.

This is the Innosql version of the Slow_log table structure, where logical_reads and physical_reads add fields to Innosql. Similarly, the output of the slow log file is increased by two fields as follows:

In addition to the details described above, the MySQL slow log module has several features that are worth noting:

1. The slow log count and the time recorded in the slow log do not include the time it takes for the lock to be acquired before the SQL statement starts executing;
2. MySQL writes to the slow log after the SQL statement has been executed and the locks held are freed, so the order of the SQL statements in the slow log does not accurately reflect the order in which the SQL statements are actually executed;
3. Each slow log contains a timestamp, and if written to a file, the Log_timestamps parameter is used to convert the slow log timestamp to the time of the specified time zone. However, this parameter does not work for slow logs in the Mysql.slow_log table;
4. You can set log_slow_slave_statements to turn on the slow log function of MySQL from the library; ALTER table, ANALYZE table, CHECK table, CREATE Index, DROP Index, Table management operations such as OPTIMIZE table, and REPAIR table can also be recorded in a slow log, which can be opened via the log_slow_admin_statements option.

MySQL slow log function analysis and optimization enhancements