5.3 Identifying Slow Queries

Figuring out which queries are slow is usually easier than figuring out why they're slow and making the necessary changes to fix them. The easiest way to track them is to let MySQL do some of the work for you. By enabling the slow query log, you instruct MySQL to log every query that takes longer than a specified number of seconds. In addition to the query, it also logs some other metadata.

Here's an example record from a slow query log:

# Time: 030303  0:51:27

# User@Host: user[user] @ client.example.com [192.168.50.12]

# Query_time: 25  Lock_time: 0  Rows_sent: 3949  Rows_examined: 378036

select ArticleHtmlFiles.SourceTag, ArticleHtmlFiles.AuxId from ArticleHtmlFiles left 

join Headlines on ArticleHtmlFiles.SourceTag = Headlines.SourceTag and 

ArticleHtmlFiles.AuxId = Headlines.AuxId where Headlines.AuxId is NULL;

While the log contains a lot of useful information, there's one very important bit of information missing: an idea of why the query was slow. Sure, if the log says 12,000,000 rows were examined and 1,200,000 sent to the client, you know why it was slow. But things are rarely that clear cut. Worse yet, you may find a slow query, paste it into your favorite MySQL client, and find that it executes in a fraction of a second.

You must be careful not to read too much information into the slow query log. When a query appears in the log, it doesn't mean that it's a bad query—or even a slow one. It simply means that the query took a long time then. It doesn't mean that the query will take a long time now or in the future.

There are any number of reasons why a query may be slow at one time but not at others:

• A table may have been locked, causing the query to wait. The Lock_time indicates how long the query waited for locks to be released.

• None of the data or indexes may have been cached in memory yet. This is common when MySQL is first started or hasn't been well tuned. Chapter 4 covers this in more detail.

• A nightly backup process was running, making all disk I/O considerably slower.

• The server may have been handling hundreds of other unrelated queries at that same time, and there simply wasn't enough CPU power to do the job efficiently.

The list could go on. The bottom line is this: the slow query log is nothing more than a partial record of what happened. You can use it to generate a list of possible suspects, but you really need to investigate each of them in more depth. Of course, if you happen to see the same query appearing in the log over and over, there's a very good chance you have a slow query on your hands.

MySQL also comes with mysqldumpslow, a Perl script that can summarize the slow query log and provide a better idea of how often each slower query executes. That way you don't waste time trying to optimize a 30-second slow query that runs once a day, while there are five other 2-second slow queries that run thousands of time per day.

Appendix B contains information on using mytop to perform real-time query monitoring, including slow queries.