You SSH in, do a textbook top and there you see it: mysqld sucking up 99.9% of CPU. Cold sweats. The Linux machine's Load Average through the roof. The database is suffering, and you along with it.

These days I've been wrestling with an epic bottleneck. You have a PHP application that ran like a shot a year ago, but now that the records table has passed a million rows, suddenly everything becomes unmanageable. Today I don't want to talk to you about how to design the database or denormalize it to gain performance (we already saw that). Today we're getting into the mud with something more direct: how to know exactly what the hell MySQL is doing with our query.

The classic EXPLAIN

The first step when you catch a slow query in your slow query log (I hope you have it enabled in your my.cnf) is to slap an EXPLAIN in front of it. This is basic, but I see a lot of people relying on intuition instead of looking at the data.

EXPLAIN SELECT p.id, p.titulo, c.nombre 
FROM posts p 
JOIN categorias c ON p.cat_id = c.id 
WHERE p.estado = 'publicado' 
ORDER BY p.fecha_publicacion DESC LIMIT 50;

If in the Extra column you see things like Using filesort or Using temporary, you have a problem. It means MySQL is creating temporary tables on disk or loading everything into memory to sort it, instead of using an index. This destroys performance if you have a lot of concurrent load.

Getting into the guts: SHOW PROFILES

But sometimes EXPLAIN falls short. It tells you the execution plan, but not exactly where the time is being spent. Since MySQL 5.0.37 (and now in the 5.1 versions we usually have mounted on web servers), we have a hidden gem that many people ignore: profiling.

To use it, you first have to enable it in your MySQL console session:

mysql> SET profiling = 1;

Then, you launch your damn slow query, the one that takes 4 seconds to return results. Once it finishes, you run:

mysql> SHOW PROFILES;

This will return a table with the Query_ID and the total execution time. Let's suppose our conflicting query has ID 1. Now comes the real magic:

mysql> SHOW PROFILE FOR QUERY 1;

The result is a microscopic breakdown of the execution threads. You're going to see things like this:

+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000021 |
| Opening tables       | 0.000014 |
| System lock          | 0.000006 |
| Table lock           | 0.000010 |
| init                 | 0.000022 |
| optimizing           | 0.000005 |
| statistics           | 0.000011 |
| preparing            | 0.000010 |
| executing            | 0.000003 |
| Copying to tmp table | 3.120562 |
| Sorting result       | 0.540121 |
| Sending data         | 0.231014 |
| end                  | 0.000005 |
| query end            | 0.000004 |
| freeing items        | 0.000012 |
| closing tables       | 0.000008 |
| logging slow query   | 0.000003 |
| cleaning up          | 0.000004 |
+----------------------+----------+

Boom! There you have it. In this real example, the problem isn't that it fetches a lot of data (Sending data takes little time), but that it spends 3 damn seconds copying data to a temporary table on disk (Copying to tmp table). This happens a lot when the temporary table is too large for the memory parameters (tmp_table_size and max_heap_table_size) and MySQL decides to dump it to disk, which is infinitely slower.

Conclusion

Profiling queries this way is pure craftsmanship, and saves you countless hours of shooting in the dark wildly changing indexes or rewriting code.

We're handling more and more gigs of data every time and MySQL does what it can, but having to scrutinize processor time millisecond by millisecond from the console feels like something from another era.

See you around.