Back around November 2005, I started working on query profiling in MySQL via the SHOW PROFILE and SHOW PROFILES commands. It’s been an interesting ride, but profiling support is finally available in public releases of MySQL starting with MySQL Community 5.0.37!
I had a few thoughts on the process and the feature that I’d like to share:
It’s been rough — Although everyone at MySQL who had seen the patch had wildly positive feedback about it, it took almost a year and a half to get things committed. Chad Miller took up my cause (back in December?) with the profiling patch as well as many others, and things actually started making progress. Thanks Chad!
Things were changed — In order to accept the feature, MySQL wanted a few things changed, which Chad handled. An interface using INFORMATION_SCHEMA was added, which I don’t entirely agree with, and the times and statistics returned were changed to absolute instead of cumulative. More on this below.
Absolute times are misleading — With SHOW PROFILE you will see rows like this:
| query end | 0.00028300 |
Does that mean it took 0.283ms to end the query? Not necessarily. The only way SHOW PROFILE knows when to cut off the timer is when the status next changes. Since the status messages were only meant to be informational, and in fact many of them were never meant to be seen in the first place, the status is not always changed in logical places in order to collect accurate timestamps this way.
My original patch only used cumulative numbers—they don’t imply any given amount of time spent in a particular place, just the total time or statistics collected at the moment the status was changed. I may submit a patch to once again reveal this information with e.g. SHOW CUMULATIVE PROFILE, as it seems very unlikely that the powers that be will allow it to be changed now.
Status messages need some updating — The last phase of the profiling patch that has yet to be done is to go through all of the status messages, cleaning them up where appropriate, and adding new messages to display more useful profiles. Perhaps I will have time to work on this soon.
Let me know how you like profiling and if you manage to make use of it!
Kaj ArnÃ¶’s blog » Blog Archive » MySQL 5.0.37 Community Server, Contributions and Binaries
I assume this only works when only one session is running any queries, since getrusage() returns status for the entire process, not just a single thread?
There is no portable way to get per-thread resource information, although most OSes provide something: GetThreadTimes on Windows, /proc/*/lwp/*/lwpusage on Solaris, /proc/*/stat on Linux (only works on pre-NPTL kernels), getrusage(RUSAGE_THREAD) on AIX.
That’s correct. It’s currently implemented as process-wide using getrusage(). Eventually it should be implemented using the various methods applicable on various OSes (at very least this should be easy-ish on Windows and Solaris). But, you’re absolutely right, there is no portable way to get thread-specific rusage information. This was included as a fairly large caveat when I submitted the patch — doesn’t look like it made it to the MySQL.com documentation.
Everybody Dance Now » MySQL Query Profiling
Hi, great job!
Could you give more information about results of PROFILE? The documentation is very basic.