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.
With that module somewhere on your system, you can now do the following: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
That printed out something similar to 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);
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.
|
---|
Replies are listed 'Best First'. | |
---|---|
Re: Mysql CPU / time profiling
by ahmad (Hermit) on Aug 17, 2010 at 03:44 UTC |