Thursday, March 28, 2013

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.

how to read mysql slow query log

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:

15 comments:

  1. This comment has been removed by the author.

    ReplyDelete
  2. nice blog and very informative and now i would like to share something. With the help of wordpress plugin developer we can get developed superb wordpress website at affordable cost.

    ReplyDelete
  3. I'm not a developer, i always use the free online timestamp generator to create the unix timestamp.

    ReplyDelete
  4. I have a point which i don't understand clearly.
    # Time: 130320 7:30:26
    >The first line shows the time the query was logged.
    This is the time:
    - Query begin to execute
    Or query execute finishing?
    Thank

    ReplyDelete
  5. Thank you for your clear explanation. You can develop Digital Marketing Company in Chennai with our industry experts best training

    ReplyDelete
  6. Hey, good day
    Thanks for sharing such valuable information.i want more these type of informatiove blogs, really thankful.SEO Company in Chennai

    ReplyDelete
  7. The blog is absolutely truly incredible. Lots of large information and inspiration, both of which we all need.
    Web Designing Company in Bangalore, Web Development Company Bangalore

    ReplyDelete
  8. Thanks for the information. Helped us to convince most on how this process works and what they could achieve by following these guidelines.
    UI Designing Companies in Bangalore, Web Application Development Services in Bangalore

    ReplyDelete
  9. Have you been thinking about the power sources and the tiles whom use blocks I wanted to thank you for this great read!! I definitely enjoyed every little bit of it and I have you bookmarked to check out the new stuff you post. java training in jalandhar

    ReplyDelete
  10. This blog is having the general information. Got a creative work and this is very different one.We have to develop our creativity mind.This blog helps for this. Thank you for this blog. This is very interesting and useful.

    iOS App Development Company

    ReplyDelete
  11. It is a great sharing...I am very much pleased with the contents you have mentioned. I wanted to thank you for this great article. Web Design Sydney ,Logo Design Sydney

    ReplyDelete