Adam Innes · Blog

Find Your Slow Queries Before Your Users Do

· 3 min · mysql, performance, databases, lamp

When a PHP page is slow, it’s often just waiting on MySQL, and frequently on one or two queries that were fine with a thousand rows and fall over at a million. The good news is MySQL will tell you exactly which queries those are, if you ask. Here’s the short version of asking, using MySQL 5.5 (5.5.11 came out last week, per the 5.5 release notes).

Turn on the slow query log

The slow query log is off by default, and the MySQL 5.5 Reference Manual documents the settings that control it. They go in the [mysqld] section of my.cnf:

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1
log_queries_not_using_indexes = 1

long_query_time is in seconds and defaults to 10, which is far too patient for a web page. The minimum is 0, and when logging to a file you can use fractions like 0.5. log_queries_not_using_indexes also logs queries that don’t use indexes, even if they’re fast today. That’s how you catch the query that will be slow next month, but the log can grow quickly with it on, so keep an eye on disk space.

You don’t have to restart to try this. All of these are dynamic, so you can flip them on from a client:

SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;
SET GLOBAL log_queries_not_using_indexes = 'ON';

One catch: long_query_time also has a session value, and changing the global value only affects connections opened after the change. If your app keeps persistent connections around, they’ll keep the old threshold until they reconnect. Put the settings in my.cnf too, or they’re gone at the next restart.

Two more things the manual points out. Lock wait time isn’t counted as execution time, and the log can contain passwords from logged statements, so treat the file like it’s sensitive.

Summarize it with mysqldumpslow

After a day of normal traffic, the log will be long and repetitive. Each entry has a header with Query_time, Lock_time, Rows_sent and Rows_examined, followed by the statement. Reading it raw is miserable. mysqldumpslow ships with MySQL and groups queries that differ only in their values, replacing numbers with N and strings with 'S':

mysqldumpslow -s t -t 10 /var/log/mysql/mysql-slow.log

-s t sorts by query time and -t 10 shows the top ten. -s c sorts by count, which is worth running too. A 2 second query that runs once a night matters less than a 0.3 second query on every page view. When you go back to the raw log for a query, I’d pay special attention to entries where Rows_examined is huge compared to Rows_sent, since that usually means MySQL read far more of the table than it needed to return a handful of rows.

Read EXPLAIN

Take the worst query and put EXPLAIN in front of it. In 5.5, EXPLAIN works on SELECT statements, so for a slow UPDATE, explain the matching SELECT. Say the log keeps showing this:

EXPLAIN SELECT id, total FROM orders
WHERE customer_id = 42 ORDER BY created_at DESC\G

On a table with no useful index you’d see something along these lines:

         type: ALL
          key: NULL
         rows: 481220
        Extra: Using where; Using filesort

Three columns tell most of the story. type is the join type, and the manual orders them from best to worst: system and const at the top, then things like eq_ref, ref and range, with ALL at the bottom. ALL means a full table scan. key is the index MySQL actually chose, and NULL means it found none to use. rows is how many rows MySQL thinks it has to examine, an estimate for InnoDB. The manual also says to look out for Using filesort and Using temporary in Extra if you want queries as fast as possible.

Add the one index

This query filters on customer_id and sorts on created_at, so one index on both columns, in that order, covers it:

ALTER TABLE orders ADD INDEX idx_customer_created (customer_id, created_at);

Run the same EXPLAIN again and you’re hoping for type: ref, key: idx_customer_created and a rows estimate in the dozens instead of the hundreds of thousands. Because customer_id is compared to a constant, the manual’s ORDER BY section says MySQL can use that index to return rows in created_at order, so the filesort should go away too. Column order matters here. An index on (created_at, customer_id) wouldn’t help this query nearly as much, because MySQL uses the leftmost part of an index first.

Adding an index to a big table still takes time, so do it in a quiet window. The manual does say the InnoDB in 5.5 can create and drop indexes with much less impact than before, which makes this less scary than it used to be.

The takeaway

Leave the slow query log on with a sensible threshold, run mysqldumpslow every so often, and EXPLAIN the top entry. The fix is often not a dramatic rewrite but one missing index, and you’ll find it before the support email does.

← all posts