MySQL Query Time Histogram

When doing MySQL performance tuning on a live server it is often hard to tell what impact there will be on all queries as sometimes by increasing one of the MySQL caches you can make some queries to execute faster but others might get actually slower. However, depending on your environment, it might not necessarily be a bad thing. For example in web serving if most queries would execute within 0.1s but some odd queries need 5s to complete it is generally very bad as user would need to wait at least 5s to get a web page. Now if by some tuning you manage to get these long queries down to below 1s with the cost of getting some sub 0.1s queries taking more time but still less than 1s it would generally be a very good thing to do. Of course in other environments the time requirements might be different but the principle is the same.

Now it is actually very easy to get such a distribution of number of queries being executed by a given MySQL instance within a given time slot if you use DTrace.

 1s resolution                                    
          value  ------------- Distribution ------------- count   
            < 0 |                                         0       
              0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4700573 
              1 |                                         6366    
              2 |                                         35      
              3 |                                         23      
              4 |                                         39      
              5 |                                         8       
              6 |                                         6       
              7 |                                         5       
              8 |                                         7       
              9 |                                         4       
          >= 10 |                                         9       

Running for 73344 seconds.

The above histogram shows that 4,7mln queries were executed below 1s each, then for another 6366 queries it took between 1-2s for each query to execute, and so on. Now lets do some tuning and see the results again (of course you want to measure for a similar amount of time during similar period of activity - these are just examples):

 1s resolution                                    
          value  ------------- Distribution ------------- count   
            < 0 |                                         0       
              0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4686051     
              1 |                                         2972       
              2 |                                         0       

Running for 73024 seconds.

That is much better. It is of course very easy to change the resolution of the histogram - but I will leave it for you.

The script requires 2 arguments - PID of a database and how often it should refresh its output, for example in order to get an output every 10s for a database running with PID 12345 run the script as:

./mysql_query_time_distribution.d 12345 10s

The script doesn't distinguish between cached and non-cached queries, it doesn't detect bad (wrong syntax) queries either - however it is relatively easy to extend it to do so (maybe another blog entry one day). It should work fine with all MySQL versions 5.0.x and 5.1.x, possibly with other versions as well.

# cat mysql_query_time_distribution.d
#!/usr/sbin/dtrace -qs


BEGIN
{
 start=timestamp;
}

pid$1::*mysql_parse*:entry
{
 self->t=timestamp;
}

pid$1::*mysql_parse*:return
/ self->t /
{
 @["1s resolution"]=lquantize((timestamp-self->t)/1000000000,0,10);

 self->t=0;
}

tick-$2
{
 printa(@);
 printf("Running for %d seconds.\n", (timestamp-start)/1000000000);
}