HowTo: Read the MySQL Slow Query Log

How to read the MySQL Slow Query Log

If you followed along with the first post in our MySQL Optimization Series, you learned how to enable slow query logging on mysql and should have that turned on. (If not go ahead and follow the steps in that article now). Today we're going to take a look at how to read the slow query log and see what we can do with this data.

Go ahead and tail your slow query log and make sure you have at least one slow query in there. If you don't you can make one:

root@server# mysql -e 'SELECT SLEEP(8);'

All the above query will do is "sleep" (do nothing) for 8 seconds. This should be long enough to be logged in your slow query log (I usually recommend logging queries taking longer than 2 or 3 seconds)

First let's check out what a slow query log entry looks like:

root@server# tail /var/log/slowqueries
# Time: 130320  7:30:26
# User@Host: db_user[db_database] @ localhost []
# Query_time: 4.545309  Lock_time: 0.000069 Rows_sent: 219  Rows_examined: 254
SET timestamp=1363779026;
SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes';

Let's go over what each line means:

• The first line shows the time the query was logged. The format is YYMMDD H:M:S. We can see the query above was logged at 2013 March 20th at 7:30am - NOTE: This is server time, which may be different from your local time
• Next, we'll see the MySQL user, database, and hostname
• The third line shows the total query time, the Lock time, the number of Rows "sent" or returned, and the number of rows examined during the query.
• Below that you'll see SET timestamp=UNIXTIME; < this is the time the query actually happened. It is good to check that you're not looking at a problem that happened months ago if you're trying to figure out why something is slow right now. I'll explain how to turn that into a usable time below
• The final line shows the full query.

To get a human-readable timestamp from the Unix Epoch, you can use the date -d command, type date -d @ (including the @ sign) and paste the timestamp from the log immediately after the @ (no space):

root@server# date -d @1363779026
Wed Mar 20 07:30:26 EDT 2013

In this case we can see the query was run and logged at the same time - on an overloaded server that may not always be the case. So remember that the SET timestamp= value is when the actual query was run.

Now I'm going to show you how I solved a real problem on one of my websites using the mysql slow query log. Your query is going to be different, but the information is the same.

I am using a plugin called Tweet Blender on a Wordpress blog (different site) to automatically display relevant tweets to my keywords. Unfortunately someone either realized that or just happened to spam Twitter with one of my keywords in the tweet or username - either way, the end result was that I was displaying Twitter spam on my site. Because tweets only stay on there for a short time, this was not something I noticed on the actual site. But when I looked in my slow query log, it was obvious.

I had several very similar queries showing a tweet with spammy text (always the same) and after a while the number of queries caused some of them to run slow. Most people would have likely had their sites suspended or getting errors if this happened because it was a fairly large number of requests, but my server is well tuned for performance, so there was no noticeable effect. Luckily I am logging slow queries so I was able to see this information and quickly determine the issue.

Fixing it was simple - Tweet Blender has awesome filtering features so I just added that Twitter username to my "exclude" list (along with several more spam keywords) and it hasn't been an issue since. It does show how useful it is to monitor your sites and logs, even if it's just a quick check once a week on each site / server.

And that is how you read the slow query log in MySQL. Simple and useful, right?

If you want help making mysql faster, Call A Developer.

Further Reading:

• MySQL in a Nutshell (O'Reilly)
• Official MySQL Site
• Learning MySQL
• MySQL Wikipedia
• High Performance MySQL: Optimization, Backups, and Replication