Photo by davesag

MySQL 5.037 added a profiler, and I've been using it to track down bottlenecks in my email analysis. If you're doing any serious database access, it will be a godsend. I'd recommend starting by looking through the official introduction but here's the highlights:

– Log into the mysql command line client
– type set profiling=1;
– Run your slow query (eg SELECT * FROM messages WHERE fromaddress='pete@petewarden.com';)
– type SHOW PROFILES;

You should now see a table with a single row, with the number 1 to the left of your query.

– type SHOW PROFILE FOR QUERY 1;

You'll see a table summarizing how long each stage of executing the query took:

+--------------------+-----------+
| Status       | Duration |
+--------------------+-----------+
| (initialization)  | 0.000063 | 
| Opening tables   | 0.000015 | 
| System lock    | 0.000005 | 
| Table lock     | 0.120696 | 
| init        | 0.000056 | 
| optimizing     | 0.000017 | 
| statistics     | 0.000249 | 
| preparing     | 0.000026 | 
| executing     | 0.000008 | 
| Sorting result   | 0.000005 | 
| Sending data    | 11.371813 | 
| end        | 0.000019 | 
| query end     | 0.000006 | 
| freeing items   | 0.00002  | 
| closing tables   | 0.000011 | 
| logging slow query | 0.000004 | 
+--------------------+-----------+
16 rows in set (0.00 sec)

Some of the status names were self-explanatory. If I saw a lot of time in Table lock I knew that had to be waiting for another process to finish updating the same table. What on earth does Sending Data mean though?

I eventually found the answer in the list of thread states, after chasing some links from the profile reference page.

The entry for Sending Data is The thread is processing rows for a SELECT statement and also is sending data to the client. That still didn't help me understand why it was stuck in that state for so long. The open-source nature of MySQL came to the rescue. By doing SHOW PROFILE source FOR QUERY 1; I got this table:

+--------------------+-----------+-----------------------+---------------+-------------+
| Status       | Duration | Source_function    | Source_file  | Source_line |
+--------------------+-----------+-----------------------+---------------+-------------+
...
| Sending data    | 11.371813 | mysql_select     | sql_select.cc |    2287 | 
...
+--------------------+-----------+-----------------------+---------------+-------------+

That told me exactly which file and function was taking all that time. By heading over to the MySQL product archives for my 5.0.45 version, I was able to download a snapshot of the full source code. If you have a different version, go to the list of releases, open the page for yours and then look for the source link at the bottom.

I brought up that function and could see exactly what the underlying code was doing. It still didn't completely clear up what was happening, but I think it was getting jammed on a lock waiting for another thread in my case, so I was able to focus on other simultaneous accesses to the database as the culprit.

I'm mentioning this last, but it should be the first thing you try. The most useful tool for debugging slow performance is putting EXPLAIN at the start of your query and seeing what the SQL optimizer thinks of it. Look at whether it has found an index to use. If it hasn't, it's scanning rows to check their values which rapidly makes it unusable as your dataset gets larger. Look at the far right box for notes on optimizations. If you see Using filesort when you're ordering your results, run screaming and reindex your data to allow fast sorts, since this also takes forever with lots of data.