MySQL Logo

In my previous post, Messing with MySQL’s Global State, I talked about how to use the set command inside MySQL to change variables. In this post, I will explain how you can use the set command to turn on MySQL’s slow query log and what to do with it.

Please note: All examples in this article were written using MySQL 5.5 and done in a development environment. Please do not try this in a production environment unless you are sure of the ramifications.

What’s the Slow Query Log?

One of the annoying things about all databases is that they process a LOT of information. It’s their job really. But it makes it difficult for programmers like you and I to figure out where problems are because queries that are taking a lot of time can be running with 100 other queries that aren’t and we’re none the wiser. Trying to time a show full process list in the exact seconds a long running query is running can be difficult if not impossible.

MySQL provides a feature called the slow query log which can be used to log queries that take more than a threshold of seconds. It can also log queries that take less than this threshold but aren’t using indexes. The non-indexed queries are queries that might not be a problem today but could cause problems in the future (and in my experience usually do on a holiday weekend).

Enable the Slow Query Log

MySQL provides several variables that allow us to tweak the slow query log:

mysql> show global variables like "%slow_query%";
+---------------------+----------------------------------------------+
| Variable_name       | Value                                        |
+---------------------+----------------------------------------------+
| slow_query_log      | OFF                                          |
| slow_query_log_file | /var/lib/mysql/ubuntu-512mb-nyc3-01-slow.log |
+---------------------+----------------------------------------------+
4 rows in set (0.00 sec)

mysql> show global variables like "%long_query%";
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

To enable the log we’re going to run the following commands:

set global slow_query_log = "On";
set global slow_query_log_file = "/var/lib/mysql/slow-2018-10-30.log";

These two commands turn on the slow query log (set global slow_query_log = "On";) and tell it where to save the file to (set global slow_query_log_file = "/var/lib/mysql/slow-2018-10-30.log";). I recommend setting the file name to the date you started the file from so you can collect several days worth of information and remember when it was started. You can also write a script to automatically change it every day/week/whatever if you need to break it up (super helpful if your server is processing a lot of queries).

As soon as you set these commands a new file will be created:

# tail /var/lib/mysql/slow-2018-10-30.log
/usr/sbin/mysqld, Version: 5.5.46-0ubuntu0.14.04.2 ((Ubuntu)). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument

As time goes by you will start seeing entries like the following:

# Time: 181105 20:34:44
# User@Host: wordpress[wordpress] @ localhost []
# Query_time: 0.000554  Lock_time: 0.000052 Rows_sent: 128  Rows_examined: 144
use wordpress;
SET timestamp=1541468084;
SELECT option_name, option_value FROM wp_8_options WHERE autoload = 'yes';

This shows that a query was run on the “wordpress” database at 1541468084. The query took 0.000554 seconds and MySQL examined 144 rows but only sent 128.

The annoying thing about this log is that unless you’re willing to walk through all the queries your server runs and look for patterns it’s not completely helpful.

Enter mysqldumpslow

mysqldumpslow is a command that will take the slow query log and summarize it so we can better act on it’s information.

For example if we can run the following:

mysqldumpslow -s at /var/lib/mysql/slow-2018-10-30.log

**snip**

Count: 2  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=64.0 (128), wordpress[wordpress]@localhost
  SELECT option_name, option_value FROM wp_8_options WHERE autoload = 'S'

**snip**

This shows the server has run a query that looks like SELECT option_name, option_value FROM wp_8_options WHERE autoload = 'S' 2 times and on average it returned 64 rows while examining 128. Note that the ‘yes’ from above full query was turned into an ‘S’ in the digested version. This is because mysqldumpslow is trying to group the queries as best as it possibly can so the parameters get turned into generic values.

We sorted by “Average Time” (-s at flag) so we can see which queries take the longest on average. This is helpful to find which queries are taking the longest (duh?). You can also sort by count (-s c) to see which queries are being performed the most (might be a good option for caching the result). I also find it helpful to sort based on the average number of rows sent (-s ar) which is useful for finding queries that might be returning too much information to your application.

Finding Our Performance Problems

Now that we’ve seen the basics on how to enable the slow query log and how to get a digest of its information we need to start finding our performance problems. With the above changes MySQL is logging queries that take more than 10 seconds to complete. This is an okay default but it’s super easy to have a page that has 2 four second queries which won’t be logged because individually they each take less than 10 seconds.

In order to decrease the threshold for what counts as a slow query we’re going to adjust the long_query_time variable. The long_query_time variable stores the number of second after which a query is considered “slow”. I recommend starting out 5 seconds.

set global long_query_time = 5;

Then you should:

  1. Collect data for a day or a week (or whatever fits your application’s usage)
  2. Analyze the data by running mysqldumpslow on the results
  3. Fix the results from the analysis by adding indexes or rewrite queries that are causing problems
  4. Repeat 1-3 until you have nothing else to fix (some queries are beyond help)
  5. Decrease the long_query_time by 1

Eventually you’ll hit a point where you have long_query_time set to 1 and you’ll want to decrease long_query_time to 0. Don’t do it. When you set it to 0, MySQL will log EVERY query. It makes sense if you think about it but it might not help your performance problems anymore.

The positive side of setting it to 0 is that it can be helpful to see when you’re running the same query over and over again which might benefit from some caching. An example is when settings are stored inside the database and every page load requires the settings (I’m looking at you Wordpress).

set global long_query_time = 0;

After long_query_time = 1

Now that you’ve successfully fixed or eliminated all the queries that take more than 1 second it’s time to start looking for queries that might cause problems in the future. A lot of the time queries are originally written with a handful of rows because developers are creating a new feature with test data in it. Unless they’re careful it’s easy to write a query using columns that don’t have an index (I’ve been guilty of this myself). As the application is used the query starts to get run on 1k rows, then 2k, rows and eventually millions of rows. If the query is lacking the indexes it needs this can drastically slow down your application.

To help elivate this problem we can have MySQL log queries that aren’t using an index and it can be set to do this using the “log_queries_not_using_indexes” variable.

set global log_queries_not_using_indexes = “On”;

Now you can repeat the Collect/Analyze/Fix cycle from above to fix these queries.

A Note on log_slow_quries

In older posts online you might see references to the log_slow_quries. This was replaced by the slow_query_log variable.

From MySQL.com:

The –log-slow-queries option is deprecated and is removed (along with the log_slow_queries system variable) in MySQL 5.6. Instead, use the –slow_query_log option to enable the slow query log and the –slow_query_log_file=file_name option to set the slow query log file name.

https://dev.mysql.com/doc/refman/5.5/en/server-options.html#option_mysqld_log-slow-queries

In Conclusion

Hopefully this post will help you find performance problems on your own application or maybe I missed something. If so let me know in the comments.