Slow Query Log analyzes tools

Another way to analyse your slow queries is to generate statistics which indexes are used, just like mysql_explain_log from the standard distribution does for the general query log.

You can get mysql_explain_slow_log on willamowius.de.

Rene,

The patch for 5.0.26 is here:
http://www.mysqlperformanceblog.com/files/patches/patch.slow-micro.5.0.24a.diff

Firstly, thanks for your great work!

I used slow query log parser to analyze a slow-query-log yesterday. I seems that all of the result looking good, but I see a very-long query at last. Maybe the script has some bugs on numberic-formating? Could you help me to fix it?

OUTPUT:

### 2846 Queries
### Total time: 18446744073826.7, Average time: 6481638817.22652
### Taking 0.020004 to 18446744073709.074210.000159 seconds to complete
### Rows analyzed 0 – 762

Peter, Vadim

I’m using MySQL 5.0.18. It’s not quite clear to me – does your patch fits that version.
Also, can You place somewhere/how more detailed instruction how to apply the patch.

Thanks,
M.D.

Dear Vadim,

Thank you very much for the actualised patch file!
Do you have already one for MySQL 5.0.27?
It should not be very different, because only one bug has been fixed.
http://dev.mysql.com/downloads/mysql/5.0.html

Best regards,
René

For Your information, I’ve resently written the similar tool for regular query log to fetch the top of most popular queries.
You can check it out at http://sourceforge.net/projects/myprofi or at http://myprofi.sourceforge.net for more details.

This tool wouldn’t give you the execution time based statistics, but outputs an overview of the most frequently run queries, so you could speedup the the overall db performance by optimizing the most popular queries.

In addition I would like to mention, that Your parser does not take into account all possible string escaping ways, like doubeling quotes, escaping with slash etc. Also would be more useful to group structures like “IN (N,N,N,N,N)” into “IN (N)”.

Dear Peter,

I reimplemented the mysql_slow_log_parser in PHP in order to provide an even more filtered result.
If you want me to send it, just comment this entry, because there is no attachment function here.

# Apply filter to log file once
php mysql_slow_log_parser.php mysql-slow-queries.log

Options:
-T=min_query_time Include only queries which took as long as min_query_time seconds or longer [default: 1]
-R=min_rows_examined Include only queries which examined min_rows_examined rows or more

-iu=include_user Include only queries which contain include_user in the user field [multiple]
-eu=exclude_user Exclude all queries which contain exclude_user in the user field [multiple]
-iq=include_query Include only queries which contain the string include_query (i.e. database or table name) [multiple]

–filter-duplicates Output only unique query strings with additional statistics: max_query_time, max_rows_examined, execution count [default sorting: max_query_time, max_rows_examined]

[multiple] options can be passed more than once to set multiple values.

Best regards,
René

> 16. peter
Hei, peter,

I have finally succeeded with impementing the support for sorting by max/average/total execution time of slow queries into MyProfi. But unfortunately i have no chance to try it on patched mysql version, so i tested it just with regular slow query log. You could try the latest version of MyProfi by taking it from project’s download page. Hope it can be useful tool for measuring the database performance on query level.

Dear Peter,

I finished the Python version, which is usually 3-5 times faster than the PHP5 version according to my personal tests, depending on the log size.

Usage Examples:

# Filter slow queries executed from other users than root for at least 3 seconds, remove duplicates and save result to file
php mysql_filter_slow_log.php -T=3 -eu=root –no-duplicates mysql-slow-queries.log

# Start permanent filtering of all slow queries from now on: at least 3 seconds or examining 10000 rows, exclude users root and test
tail -f -n 0 linux-slow.log | python mysql_filter_slow_log.py -T=3 -R=10000 -eu=root -eu=test &
# (-n 0 outputs only lines generated after start of tail)

# Stop permanent filtering
kill ps auxww | grep 'tail -f -n 0 linux-slow.log' | egrep -v grep | awk '{print 2}'

-s=WORD
what to sort by (t, at, l, al, r, ar etc)

what’s difference between these option above?

Unless I’m missing something, it seems that there is a bug in all of these patches. I’m pretty sure the line in my_time.cc that reads:
newtime/= (frequency * 1000000);
instead should be:
newtime/= (frequency / 1000000);

Please confirm!

Did you think of using a mySQL Proxy script for creating the log file instead of a patch for the mySQL server?

This would make it much easier to use:
1. No need to compile the mySQL server.
2. Logging (use of mySQL Proxy) can be switched on and off by redirecting the port with iptables: http://forge.mysql.com/snippets/view.php?id=82

The mySQL Proxy script could write a logfile in the slow-log format so that your tool can use it.

Hello,

Just tried applying the latest patch
http://www.mysqlperformanceblog.com/files/patches/patch.slow-micro.5.0.41.diff
to the appropriate sources
http://downloads.mysql.com/archives.php?p=mysql-5.0&v=5.0.41
and got
Error C2143: syntax error : missing ‘)’ before ‘;’ @ c:\mysql-5.0.41-slowmicro\sql-common\my_time.c line 1244
The fix is – suprisingly 🙂 – to add a ‘)’ before ‘;’ at line 1244 @ my_time.c line 1244, so it is not really a big issue. Still it would be nice if you could update the patch

Thanks,

Mads

Mads,

Thanks, I fixed that in the patches.

Thank you so very much for this wonderful article. I have been having an incedible amount of trouble with searches on my SMF forum timing out in Apache because mysql was taking too long to run the search query. After reading this article, I was able to find my problem was that the search query was creating a temp table and populating it with topic ID’s and then building the results off that. After analyzing the long query log, I was able to write a more much more efficient SQL statement to get the job done.

Again, thank you, thank you, thank you for posting such advanced and useful information.

Here’s how i used this patch to benchmark our production server:

First, I enabled the general query log in my production server, and collected some data. I let it run for 60 hours (2 1/2 days), which captured peak times, and all typical usage.
I used a trick to turn off the general query log without restarting mysql – i moved the log file aside, touched a replacement, but didn’t give the mysql user write permision to it. I then used mysqladmin to flush all the logs, and when it couldn’t open a handle to the new general query log file, it simply stopped logging.

Now, get an identical piece of hardware as your production server – preferably built by clonig the HDD so you have identical OS and filesystem layout.
Recompile the same version of mysql, with this patch applied (we compile mysql from source ourselves anyway, so this is still a fair performance test). Get the database on it current up to the point you turned on the general query log.
To do this, i used a backup from a few weeks earlier, and used mysqlbinlog to extract the rest of the data from the binary logs, up until the start point. I could actually see the last line in the catchup sql matching one of the first in the general query log, so rewinded one second, and knew i was spot on.
You now have an identical server, with data in a state ready to be benchmarked.
It’s worth taking a database dump here, in case you want to run the benchmark again.

Now pump your query log acquired earlier through the below perl script. It’s very quick, very dirty, and probably very buggy, but seemed to work acceptably well in our case.
It rebuilds the timing, connections, and queries the server saw, based on the contents of query log – it creates a seperate thread for each connection, and runs each query at (about) the right time, relative to the start of the run.
That means if you have 60 hours worth of dump data, the script will run for 60 hours replaying it. This was important for us, because we have short bursts of very high load, long periods of quite low load, and even the odd moment of practically zero load. This recreates all of them, just like they were in real life.
It’s worth running this script on a seperate box with lot’s of cores – it’s very thread-hungry.

The script (replay_query_log.pl):

#!perl

use Time::Local;
use DBI();

# Setup who your DB host host, and a hash of copnnection passwords.
# You need one password entry for each user that connects
# in the logs you want to replay – you can get by grepping
# for ‘Connect’, and using cut/sed/sort/uniq liberally.
#
my $DBHOST=”slush”;
my %passwords = ( “user” => “pass”,
“reporting” => “reporting”,
“user-no-pw” => “”,
“etc” => “etc”
);

# skip the first 3 lines
();
();
();

# Process the query log, and build a couple of hashes from it:
#
# Hash 1: %queries – keyed by connection id and datetime,
# – is an array of all queries by that connection at that time.
# Hash 2: %starttime – keyed by connection id
# – contains the time the first query run by this conenction started
#
# The first hash is used to actually runt he queries, the second is used to
# avoid fork bombing the box, by only forking the processes when needed.

while ()
{
# datetime line
if(s/^(0[0-9])([01][0-9])([0-3][0-9])\s+(1?[0-9]):([0-5][0-9]):([0-5][0-9])//)
{
# Convert to unix epoch – makes date arithmetic dead easy.
$datetime = Time::Local::timelocal($6, $5, $4, $3, $2-1, “20”.$1);
$dt_min = $datetime if (($datetime < $dt_min) || !(defined $dt_min));
}
# query type line
if(s/^\s+([0-9]+) ((Query)|(Quit)|(Connect)|(Statistics)|(Binlog Dump Log))//)
{
# If we enter this loop, it means a new query/type has started.
# Save the old one (if it exists), and reinitialise the vars
# for the next
push @{$queries{$connection}{$datetime}}, $query if length($query);
$connection = $1;
$starttime{$connection} = $datetime if (($datetime $_)
{
sleep $now – $_;
}
# Now that the threads are due to start, we fork, and connect
foreach (@{$startconn{$_}})
{
my $conn = $_;
my $DBUSER = $dbun{$conn}[0];
my $DBNAME = $dbun{$conn}[1];
my $DBPASS = $passwords{$DBUSER};
my $pid = fork();
if($pid == 0)
{
###print “forked\n”;
my $dbh;
# Each connection has multiple queries, so we
# iterate the hash, waiting for the correct time
# to run each one.
# I use while(){ sleep 1 } rather than sleep n to
# avoid timing issues – this garauntees the query will
# run within +/- 0.5s of when it’s due, which is good
# enough for our purposes (usually).
foreach (sort keys %{$queries{$conn}})
{
my $dt = $_;
while((time() – $offset) connect(“DBI:mysql:database=$DBNAME;host=$DBHOST”,
“$DBUSER”, “$DBPASS”)
|| die “Couldn’t create dbh”;
}
foreach (@{$queries{$conn}{$_}})
{
my $sth = $dbh->prepare($_);
$sth->execute();
$sth->finish();
}
}
$dbh->disconnect();
###print “died\n”;
exit; # very important.
} else
{
# Don’t do this.
#waitpid($pid,0);
}
}
}

# done!!!

I got some quite interesting numbers our of it, and have learned a lot about how our database behaves.

Now – this is not a well tested script – it’s probably rife with bugs, so use with caution. Any bugfixes, enhancements, or comments – please post them back here.

Hopefully this will help some-one else out.

Hello,

I try this but ı wonder.

What should be the long_query_time for best performance?

Thanks

I dont understand that. So sometimes I can reach any data for that codes. We can argue this with together.

Hi,

I did not test with 5.0.18 – but you can try.