Beefy Boxes and Bandwidth Generously Provided by pair Networks
laziness, impatience, and hubris
 
PerlMonks  

Mysql CPU / time profiling

by Rhandom (Curate)
on Aug 11, 2010 at 04:43 UTC ( [id://854215]=CUFP: print w/replies, xml ) Need Help??

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:
StatusDurationCPU_userCPU_systemOther
starting0.0000170.0000000.000000Other
checking query cache for query0.0000300.0000000.000000Other
checking permissions0.0000050.0000000.000000Other
Opening tables0.0000080.0000000.000000Other
init0.0000240.0000000.000000Other
optimizing0.0000050.0000000.000000Other
executing0.0000170.0000000.000000Other
end0.0000050.0000000.000000Other
query end0.0000020.0000000.000000Other
freeing items0.0000930.0000000.000000Other
logging slow query0.0000030.0000000.000000Other
cleaning up0.0000040.0000000.000000Other
TOTAL0.0002130.0000000.000000Other

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)];

Replies are listed 'Best First'.
Re: Mysql CPU / time profiling
by ahmad (Hermit) on Aug 17, 2010 at 03:44 UTC

    Nice work, And yes it might be a good idea to add it to CPAN

Log In?
Username:
Password:

What's my password?
Create A New User
Domain Nodelet?
Node Status?
node history
Node Type: CUFP [id://854215]
Approved by Corion
help
Chatterbox?
and the web crawler heard nothing...

How do I use this?Last hourOther CB clients
Other Users?
Others pondering the Monastery: (6)
As of 2024-04-19 07:14 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    No recent polls found