Logging and analyzing slow queries in MySQL

Introduction

Slow queries can negatively impact database performance. If you don't analyze, optimize, and tune the slow queries as early as possible, the overall performance of your system will eventually degrade. Query optimization is essential to ensure high performance for the most important queries.

The slow query log feature in MySQL allows you to log all queries that take longer than a given threshold of execution time. The queries in the slow query log are good candidates to start optimizing and eliminating the bottlenecks.

This feature is not activated by default, so in this article, I'll explain how to active this feature and how to analyze the results in order to discover the bottlenecks in the data pipeline. After reading this article, you will be able to apply these concepts and techniques when you have an under-performing system.

Demo

The slow query log feature is turned off by default in MySQL, so in order to turn this feature on, we need to set the slow_query_log parameter to ON as shown in listing 01.

mysql> SET GLOBAL slow_query_log = 1;

Listing 01

When the slow query log feature is enabled, by default MySQL logs any query that takes longer than 10 seconds to execute. We can change this setting to 5 seconds using the long_query_time parameter as shown in listing 02.

mysql> SET GLOBAL long_query_time = 5;

Listing 02 

It's recommended to set up long_query_time=0 in order to log all queries, because the first step is to analyze all the queries to find out the most commonly used and the slowest ones. Be very careful while setting up long_query_time=0 because this setting will increase the I/O workload on your system (due to the writing operations) and your disk space can be filled up. One strategy is to turn this setting on for a period of time and then revert it back to log only the slow queries.

By default, the slow query log file is located at /var/lib/mysql/hostname-slow.log. We can also set up another location as shown in listing 03 using the slow_query_log_file parameter.

mysql> SET GLOBAL slow_query_log_file = '/var/log/mysql/mysql-slow.log';

Listing 03

We can also indicate to log queries not using indexes, as shown in the listing 04.

mysql> SET GLOBAL log_queries_not_using_indexes = 1;

Listing 04

While it’s important to log all queries that are not hitting indexes, it does not indicate a slow query because there are cases when the query optimizer chooses full table scan rather than using any available index; for example, if the table is still small or we’re requesting more than 25% of the total rows.

The parameter changes are lost after MySQL reboots because the parameters are set dynamically, so in order to make the changes permanent, we need to set up the parameters in the MySQL configuration file (/etc/mysql/my.cnf) as shown in listing 05.

[mysqld]
slow-query-log = 1
slow-query-log-file = /var/log/mysql/mysql-slow.log
long_query_time = 5
log-queries-not-using-indexes = 1

Listing 05

We can also check the variable/parameters values as shown in listing 06.

mysql> SHOW GLOBAL VARIABLES LIKE 'slow_query_log';
mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';

Listing 06

In order to verify that the slow query log is working correctly, we execute the following statement with a value greater than the long_query_time setting, as shown in listing 07.

mysql> SELECT SLEEP(11);

Listing 07

This query is logged due to the threshold in the execution time, as shown in listing 08.

# Time: 2017-08-04T19:24:50.630232Z
# User@Host: root[root] @ localhost []  Id:   236
# Schema:   Last_errno: 0  Killed: 0
# Query_time: 11.003017  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 57
SET timestamp=1501874690;
SELECT SLEEP(11);

Listing 08

Let’s take a look at the slow query log in listing 8.

The first line indicates what time the query completed (time at which the query was run). The next line contains user data (who ran it). The next line indicates how long the query took to run (processing time), how long a lock was required (wait time), how many rows were returned as a result, and how many rows were examined to determine the result. The final line shows the actual SQL query.

Analyzing the slow query log

We need to analyze the slow query log in order to identify the queries that impact a system. It does not always have to be the slowest queries that do this, because queries running more frequently with lower execution time (for example, a query that takes 1 seconds to run but runs thousands of times per minute) increase the workload on a system more than really slow queries running with less frequency (for example, a query that takes 60 seconds to run once a month). Really slow queries impact the system throughput, but queries running frequently generate most of the system workload.

Eventually, the slow query log grows in size, and the size is too big to analyze by simple inspection. In order to get a big picture on slow queries, MySQL provides a tool named mysqldumpslow to display the results in a way that’s easy to analyze. To use this tool, we need to pass the slow query log as the parameter, as shown in listing 09.

$ mysqldumpslow /var/log/mysql/mysql-slow.log

Listing 08

The output has the following fields:

• Count – How many times the query has been logged
• Time – Both the average time and the total time of processing time and waiting time
• Rows – Number of rows returned

We can execute this tool to discover specific problems such as “top 5 query which returned maximum rows” to find out queries with missing LIMIT clause as shown in listing 09.

$ mysqldumpslow -a -s r -t 5 /var/log/mysql/mysql-slow.log

Listing 09

We can also sort output by count (number of times query found in the slow query log) to find out the most frequent queries that can produce most of the server workload as shown in listing 10.

$ mysqldumpslow -a -s c -t 5 /var/log/mysql/mysql-slow.log

Listing 10

We can also display the top 5 queries sorted by the average query time, as shown in listing 11.

$ mysqldumpslow -t 5 -s at /var/log/mysql/localhost-slow.log

Listing 11

Conclusion

In this article, I've explained the concepts and benefits related to the slow query log feature in MySQL. You’ve learned how to activate this feature and analyze the logs.

Now you can start using this amazing feature in your own database environment to optimize your queries and eliminate bottlenecks in order to improve the performance and scalability of your systems.