Beefy Boxes and Bandwidth Generously Provided by pair Networks
Keep It Simple, Stupid

Mysql CPU / time profiling

by Rhandom (Curate)
on Aug 11, 2010 at 04:43 UTC ( #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:
checking query cache for query0.0000300.0000000.000000Other
checking permissions0.0000050.0000000.000000Other
Opening tables0.0000080.0000000.000000Other
query end0.0000020.0000000.000000Other
freeing items0.0000930.0000000.000000Other
logging slow query0.0000030.0000000.000000Other
cleaning up0.0000040.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?

What's my password?
Create A New User
Node Status?
node history
Node Type: CUFP [id://854215]
Approved by Corion
and all is quiet...

How do I use this? | Other CB clients
Other Users?
Others lurking in the Monastery: (4)
As of 2017-03-25 14:53 GMT
Find Nodes?
    Voting Booth?
    Should Pluto Get Its Planethood Back?

    Results (311 votes). Check out past polls.