Introduction to MySQL Slow Query Log

Bob Bao

May 29, 2023 • 5 min read

Note: The following content uses MySQL version 8.0.24 and tables from the Sakila sample database.

Introduction

The Slow Query Log is a log used to record query statements that take a long time to execute in a MySQL database. In addition to recording DQL (Data Query Language), may also record DDL (Data Definition Language).

Specifically, when the query time is longer than long_query_time and the number of rows checked exceeds min_examined_row_limit, the query statement will be recorded in the slow query log.

By analyzing the slow query log, you can identify query statements that take longer to execute and optimize them to improve the performance of MySQL database.

Configuration Introduction

slow_query_log

Use slow_query_log to enable or disable slow query logging. The default is off.

Example usage:

SET GLOBAL slow_query_log = 'ON';

slow_query_log_file

Use the slow_query_log_file parameter to specify the output directory of the log. The default value is host_name-slow.log.

Example usage:

SET GLOBAL slow_query_log_file = '/www/server/data/mysql-slow.log';

long_query_time

the slow query threshold (in seconds) beyond which SQL execution will be logged. The default value is 10, the minimum value is 0, and the maximum value is 31536000 (365 days).

Example usage:

SET SESSION long_query_time = 1;

min_examined_row_limit

Slow query only logs SQL with scan rows greater than this parameter. only the number of rows checked at the server level is used here, not the number of rows scanned at the storage engine level. The default value is 0.

Example usage:

SET SESSION min_examined_row_limit = 100;

log_output

Use log_output to specify the log storage method. log_output='FILE' means to store the log to a file, the default value is 'FILE'. log_output='TABLE' means to store the log to the database so that the log information is written to the mysql.slow_log table. The MySQL database supports two types of log storage at the same time, just configure them separated by commas, for example: log_output='FILE,TABLE'. Logging to a dedicated system log table consumes more system resources than logging to a file, so for those who need to enable slow query logging and need to get higher system performance, it is recommended to prefer logging to a file.

Example usage:

SET GLOBAL log_output = 'FILE';

log_slow_admin_statements

log_slow_admin_statements can be used to log table operations, including ALTER TABLE, CREATE INDEX, and so on. The default is off.

Example usage:

SET GLOBAL log_slow_admin_statements = 'ON';

log_queries_not_using_indexes

log_queries_not_using_indexes records statements that do not use indexes. If the amount of data in the table is so small that a full table scan is faster and does not use the indexes, the same will be logged. The default value is off.

If only slow_query_log and log_queries_not_using_indexes are turned on, and the other parameters are the defaults, then the slow query log will log statements that use the UNION keyword, whether or not they hit an index. This appears to be a bug that is still not fixed in version 8.0.24: https://bugs.mysql.com/bug.php?id=29244.

Example usage:

SET GLOBAL log_queries_not_using_indexes = 'ON';

log_throttle_queries_not_using_indexes

log_throttle_queries_not_using_indexes to limit the number of statements that log no indexes for 60 seconds. The default is 0, which means no limit. Assuming a positive value of n, when the first statement without indexes is logged, MySQL opens a 60-second window where statements within the number n are logged and the rest are counted as a summary message.

Example usage:

SET GLOBAL log_throttle_queries_not_using_indexes = 200;

The above is modified by dynamic configuration and restarting either MySQL or the server will cause the configuration to fail. This can be done by writing the parameters to the configuration file to make it permanent.

Example configuration:

[mysqld]
slow_query_log=1
slow_query_log_file=/www/server/data/mysql-slow.log
long_query_time=1
min_examined_row_limit=100
log_queries_not_using_indexes=1

Record condition judgment

MySQL determines whether to log the current statement to the slow query log in the following order:

If it is an administrative statement and log_slow_admin_statements is turned on, the subsequent judgment is made, otherwise it is not logged.
If the query time is greater than long_query_time or log_queries_not_using_indexes is turned on and no indexes are used, then follow up, otherwise no logging is done.
If the query statement satisfies the number of rows set by at least min_examined_row_limit, it will be followed up, otherwise it will not be logged.
If log_throttle_queries_not_using_indexes is set and the current statement meets the required number of rows, it is logged, otherwise it is not logged.

With MySQL before 8.0, query statements that hit the cache are not logged to the slow query log.

Log File Format

Example of slow query log format:

# Time: 2023-05-29T09:09:28.842627Z
# User@Host: root[root] @ localhost []  Id:    12
# Query_time: 0.007624  Lock_time: 0.000363 Rows_sent: 1000  Rows_examined: 1006
SET timestamp=1685351368;
select *
from film f
         left join language l on f.language_id = l.language_id
where l.name = 'English';

The first line: the specific time when the SQL query was executed.

The second line: the connection information, user and connection IP of the SQL query execution.

The third line: Query_time indicates the time of SQL execution, the longer it is, the slower it is, Lock_time indicates the time of waiting for table lock in MySQL server phase (not in storage engine phase), Rows_sent indicates the number of rows returned by the query, Rows_examined indicates the number of rows checked by the query, the longer it is, the more time consuming it is.

The fourth line: set the timestamp, which has no practical meaning, but only corresponds to the execution time with the first line.

The fifth row and all subsequent rows are the executed SQL statements, and the SQL may be very long. Until the next # Time.

Slow Query Log Analysis Tools

Use MySQL's own slow query logging tool, mysqldumpslow, to filter and summarize data.

Commonly used parameters are explained:

-s sort_type

the type of sorting. The following options are available for sort_type: -s

c: count Total number of executions
l: lock time
t: query time
r: number of records returned
al: average lock time
at：Average query time
ar：average number of returned records

-t N

returns the first N rows of data.

-g pattern

filter out the required information, you can write regular expressions, similar to grep command.

Example: Query the top 10 statements sorted by time that contain a left join:

mysqldumpslow -s t -t 10 -g "left join" /www/server/data/mysql-slow.log

Query results:

Reading mysql slow query log from /www/server/data/mysql-slow.log
Count: 1  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=1000.0 (1000), root[root]@localhost
  select *
  from film f
  left join language l on f.language_id = l.language_id
  where l.name = 'S'

Died at /usr/bin/mysqldumpslow line 162, <> chunk 2.

Summary

The slow query log is a log used to record query statements that take a long time to execute in a MySQL database. By analyzing the information in the slow query log, you can find out the query statements that take longer to execute and perform targeted optimization to improve the performance of MySQL database.

Author Bio

Bob (bob@moego.pet), from MoeGo R&D.

References

This work is licensed under a Creative Commons Attribution-NonCommercial-NoDerivatives 4.0 International License .