Friday, November 14, 2008

On-the-fly Mysql Query tracing with DTrace

Hearing that the MySQL database server is delivering corrupt data is not how I like to start the day, but that was the greeting when I arrived to work a couple days ago.

The claim was that an INSERT...SELECT query buried in a batch process was producing a different result than running the same query manually via the mysql client.

Since this is a production system, and a busy one at that, we don't keep the general log enabled. Restarting the server to enable logging is not an option during peak loads either.

Luckily, I stumbled on a DTrace script out there in internet land and it let me see exactly what was happening. I wish I can remember where I got it so I could give due credit. Here is the script:

#!/usr/sbin/dtrace -qs
pid$1::*dispatch_command*:entry
{
printf("%d::%s\n",tid,copyinstr(arg2));
}

Thats it. Just execute it on your Solaris 10 server passing the mysqld pid as a command line parameter and you see each query issued to the server. When you have seen enough, just cntl + c to quit.

I used this to trace the batch process and in no time, we determined that there was not one, but two inserts buried within. MySQL was acquitted. Case closed.

----------
This hardly scratches the surface of what I believe DTrace can be used for. I've used it a bit to trace some function calls in mysqld ( using the pid provider), and it does offer an interesting glimpse into MySQL's inner self.