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:
To enable the log we’re going to run the following commands:
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:
As time goes by you will start seeing entries like the following:
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.
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:
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.
Then you should:
- Collect data for a day or a week (or whatever fits your application’s usage)
- Analyze the data by running
mysqldumpslowon the results
- Fix the results from the analysis by adding indexes or rewrite queries that are causing problems
- Repeat 1-3 until you have nothing else to fix (some queries are beyond help)
- Decrease the
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).
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.
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
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.
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.