If you use the Mysql client commandline, you'll notice that it reports the seconds elapsed for the query. This information, in addition to a quantity of other information is available if you know where to look. I previously didn't know where to look and searches on perlmonks, cpan and mysql dev didn't return too much (probably because I didn't know where to look).
So - while this isn't necessarily ground breaking, I've found it useful and wanted to record it for posterity and share it for others who may find it useful.
package MySQL::Profile;
use strict;
use warnings;
use base qw(Exporter);
use HTML::Entities qw(encode_entities);
our @EXPORT;
our @EXPORT_OK = qw(mysql_profile mysql_profile_to_table);
sub mysql_profile {
my ($dbh, $code) = @_;
$dbh->do("SET profiling = 1");
my @resp = eval { $code->($dbh) };
$dbh->do("SET profiling = 0");
my $prof = $dbh->selectall_arrayref("SHOW profile ALL", {Slice =>
+{}});
die {error => "$@", profile => $prof} if $@;
return wantarray ? ($prof, @resp) : $prof;
}
sub mysql_profile_to_table {
my $prof = shift;
my $args = shift || {};
my $fields = $args->{'fields'} || [qw(Duration CPU_user CPU_system
+)];
my $totals = {Status => 'TOTAL'};
for my $r (@$prof) {
$totals->{$_} += $r->{$_} for grep {defined($r->{$_}) && $r->{
+$_} =~ /^[\d\.]+$/} keys %$r;
}
$totals->{$_} = sprintf('%.6f', $totals->{$_}) for @$fields;
my $t = $args->{'table_head'} || "<table>\n";
$t .= "<tr><th>".join("</th><th>", 'Status', @$fields)."</th><th>O
+ther</th></tr>\n";
for my $r (@$prof, $totals) {
$t .= "<tr><td>".join("</td><td>", map {my $v = delete($r->{$_
+}); encode_entities(defined($v) ? $v : '')} 'Status', @$fields)."</td
+>"
."<td title=\"".join(",\n", map {my $v = $r->{$_}; "$_: ".
+encode_entities(defined($v) ? $v : '')} sort keys %$r)."\">Other</td>
+</tr>\n";
}
$t .= "</table>\n";
return $t;
}
=head1 ROUTINES
=over 4
=item mysql_profile
Takes a mysql DBI database handle, and a code ref. The dbh will be
passed as the first argument to the code ref. The code ref will be ca
+lled
in an eval block in order to make sure that it has a chance to restore
+ a mysql session
variable when done. Returns a $profile arrayref in scalar context. R
+eturns the
$profile as well as any items returned from the coderef in wantarray c
+ontext.
my $prof = mysql_profile($dbh, sub { shift->do($sql, {}, $arg1) });
my ($prof, @values) = mysql_profile($dbh, sub { shift->selectrow_ar
+ray($sql) } );
# you do not need to use the database handle passed to the code ref
+ or return args through
my @values;
my $prof = mysql_profile($dbh, sub {
my $sth = $dbh->prepare($sql);
$sth->execute;
@values = $sth->fetchrow;
});
=item mysql_profile_to_table
Takes a profile returned by mysql_profile and returns a simple html ta
+ble suitable for display.
my $html = mysql_profile_to_table($prof);
my $html = mysql_profile_to_table($prof, {table_head => '<table id=
+"foo">'});
=back
=cut
With that module somewhere on your system, you can now do the following:
#!/usr/bin/perl
use strict;
use warnings;
use MySQL::Profile qw(mysql_profile mysql_profile_to_table);
use DBI;
my $dbh = DBI->connect('mysql...'); # DBD::mysql handle that you provi
+de
my ($prof, $now, $earlier) = mysql_profile($dbh, sub {
shift->selectrow_array("SELECT NOW(), DATE_SUB(NOW(), INTERVAL 1 D
+AY)");
});
#print Data::Dumper->new([$prof, $now, $earlier], [qw(prof now earlier
+)])->Dump;
print mysql_profile_to_table($prof);
That printed out something similar to the following:
Status | Duration | CPU_user | CPU_system | Other |
starting | 0.000017 | 0.000000 | 0.000000 | Other |
checking query cache for query | 0.000030 | 0.000000 | 0.000000 | Other |
checking permissions | 0.000005 | 0.000000 | 0.000000 | Other |
Opening tables | 0.000008 | 0.000000 | 0.000000 | Other |
init | 0.000024 | 0.000000 | 0.000000 | Other |
optimizing | 0.000005 | 0.000000 | 0.000000 | Other |
executing | 0.000017 | 0.000000 | 0.000000 | Other |
end | 0.000005 | 0.000000 | 0.000000 | Other |
query end | 0.000002 | 0.000000 | 0.000000 | Other |
freeing items | 0.000093 | 0.000000 | 0.000000 | Other |
logging slow query | 0.000003 | 0.000000 | 0.000000 | Other |
cleaning up | 0.000004 | 0.000000 | 0.000000 | Other |
TOTAL | 0.000213 | 0.000000 | 0.000000 | Other |
Though perlmonks doesn't show it, on normal sites, the Other column has a title attribute which shows a myriad of other information such as page faults and disk IO in/out.
Enjoy!! If there is enought request, I'm sure I could post it as a CPAN module.
my @a=qw(random brilliant braindead); print $a[rand(@a)];
-
Are you posting in the right place? Check out Where do I post X? to know for sure.
-
Posts may use any of the Perl Monks Approved HTML tags. Currently these include the following:
<code> <a> <b> <big>
<blockquote> <br /> <dd>
<dl> <dt> <em> <font>
<h1> <h2> <h3> <h4>
<h5> <h6> <hr /> <i>
<li> <nbsp> <ol> <p>
<small> <strike> <strong>
<sub> <sup> <table>
<td> <th> <tr> <tt>
<u> <ul>
-
Snippets of code should be wrapped in
<code> tags not
<pre> tags. In fact, <pre>
tags should generally be avoided. If they must
be used, extreme care should be
taken to ensure that their contents do not
have long lines (<70 chars), in order to prevent
horizontal scrolling (and possible janitor
intervention).
-
Want more info? How to link
or How to display code and escape characters
are good places to start.