Identifying Slow Queries in MySQL: Slow Query Log 101

When MySQL performance issues are encountered, one of the first things troubleshooting developers do is identify long running queries and optimize them. We will take a look at a MySQL feature that helps you identify long running queries – MySQL slow query log.

Understanding the Slow Query Log

In MySQL, the slow query log consists of SQL statements that take more time to execute than defined in the long_query_time system variable. The system variable’s minimum and default values are 0 and 10 respectively. If a query execution takes more seconds than defined, the server increments the Slow_queries variable – this counter increments regardless of whether the slow query log is enabled. It is worth noting that mysqld writes a statement to the slow query log only after it has been executed and all locks have been released, so the log order might be different than the query execution order.

Enabling the Slow Query Log

In order to enable the slow query log in MySQL, follow these steps:

1. Log in to your server using SSH;
2. Log in to MySQL, provide the root password by typing mysql -u root -p;
3. Enable the slow query log by typing SET GLOBAL slow_query_log = 'ON';

When the slow query log is enabled, by default it logs any query that takes longer than 10 seconds to run. To change the interval, type the following command where x is the time in seconds:

SET GLOBAL long_query_time = x;

If no name for the slow query log file is specified, the default name is host_name-slow.log. The file is located in the /var/lib/mysql/ directory – the server creates the file there unless an absolute path to a different directory is given: in order to change the log path or the file name, run the command SET GLOBAL slow_query_log_file = '/path/filename';

To verify that the slow query log is running correctly, reset the session variables by logging out and logging back into MySQL and type the following command where x is the amount of time in seconds:

SELECT SLEEP(x);

The slow query log should now contain information about the query.

In order to disable the slow query log, run SET GLOBAL slow_query_log = 'OFF';

Diving Deeper Into the MySQL Slow Query Log

The slow query log can be optimized further by enabling certain variables or using certain options:

• In order to enable slow administrative statements to be logged inside the query log, enable the log_slow_admin_statements variable. Administrative statements include the ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE and REPAIR TABLE statements;
• To log queries not using indexes, enable the log_queries_not_using_indexes variable. It is worth noting that when queries not using indexes are logged, the slow query log may grow quickly – in order to put a rate limit on these queries, increase the log_throttle_queries_not_using_indexes variable to 1 (the default value is 0);
• The log_throttle_queries_not_using_indexes variable limits the number of queries per minute that can be written to the slow query log. The default value of 0 means no limit;
• Queries that examine fewer rows that the number set in the min_examined_row_limit variable will not be logged in the slow query log;
• By default, a replication slave does not write replicated queries to the slow query log, though this can be changed by enabling the log_slow_slave_statements system variable. This variable only has an effect if statement-based replication is used;
• The server does not log queries handled by the query cache.

It is also worth noting that the server writes less information to the slow query log if you use the --log-short-format option.

The Contents of the Slow Query Log File

When the slow query log is enabled, the server writes output to the destination specified by the log_output variable – if the destination is set to NONE, no queries will be written to the log even if the slow query log will be enabled.

The /var/log/mysql/mysql-slow.log file can only be accessed by the root user using sudo privileges – you will not be able to read the file when using another user.

Entries in the slow query log are preceded by the # character and they contain the following:

• Query_time contains the query execution time in seconds;
• Lock_time contains the time to acquire locks in seconds;
• Rows_sent contains the number of rows sent to the client;
• Rows_examined contains the number of rows examined by the server.

MySQL statement logging avoids logging passwords in statements written to the slow query log to not occur in plain text. MySQL avoids logging passwords in clear text for the CREATE USER, ALTER USER and GRANT statements with IDENTIFIED BY postfixes, the SET PASSWORD statement, the SLAVE START statement with the PASSWORD postfix, also the CREATE SERVER and ALTER SERVER statements with the OPTIONS postfix.

Using mysqldumpslow to Examine The Slow Query Log

mysqldumpslow is a tool to examine the slow query log and group similar queries together. A few tool usage examples are provided below:

• Running mysqldumpslow without any flags will show results of all the queries that ran in the database.
  For example, the query mysqldumpslow /var/log/mysql/mysql-slow.log could provide the following results (the results are an example):

Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 1 Time=1.17s (1s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
SELECT * FROM table_1

Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 15 Time=127.41s (127s) Lock=0.00s (0s) Rows=851752.0 (851752), root[root]@localhost
SELECT * FROM table_2

• The query mysqldumpslow -r -t 10 /var/log/mysql/mysql-slow.log will show you the last 10 queries in a reversed sort order.

There are all sorts of queries that can be analyzed using the mysqldumpslow tool, just play around with it.

mysqldumpslow supports various flags:

Option Name	Description
-a	Numbers will not be abstracted to N, strings will not be abstracted to S.
-n	Numbers with at least the specified number of digits will be abstracted.
-g	Only statements matching a specified pattern will be shown in the result set.
-h	Host name of the server can be provided in the log file name.
-i	Name of the server instance should be provided.
-l	Lock time should not be substracted from the total time.
-r	The sort order should be reversed.
-s	Define how to sort output. Output can be sorted by query time (“t“), average query time (“at“), lock time (“l“), average lock time (“al“), rows sent (“r“), average rows sent (“ar“) or by count (“c“).
-t	Display only the first x amount of queries.
–debug	Display debugging information.
–help	Display help message and exit.
–verbose	Enable verbose mode printing more information about what the program does.

Summary

To summarize, the slow query log feature in MySQL enables developers to log queries that exceed a specified time limit. By doing so developers can simplify the task of finding bottlenecks in MySQL query performance and eliminate inefficient or time-consuming queries.