Perl Advent Calendar 2007-12-03

Brown paper packages tied up with string

by Jason Porritt

Thanks for this timely submission Jason. — The Management

Time is precious around the holiday season. Instead of spending hours wrapping DBI calls with timers and warn statements to figure out which of your fifty-odd queries is slow today, give DBIx::Profile a try. Like the customer service counter at a department store, DBIx::Profile will take care of all your wrapping needs, reporting wall-clock and CPU time as well as the execute and fetch count for your DBI interactions.

All you have to do is use it before DBI itself:

   1 use DBIx::Profile;
   2 use DBI;
   3 $dbh->setLogFile("Yule.log"); #optional -- default STDERR
   4 $dbh->printProfile;           #optional -- default is to buffer

I prefer to include it in my Apache config file—

   PerlModule DBIx::Profile
   PerlModule Apache::DBI

—adding one line provides reporting for every application, content filter, or authentication handler on the entire site. By default, DBIx::Profile will print everything to STDERR when it disconnects from the database, though you can select a different file via $dbh->setLogFile("Yule.log"); or explicitly print the data at any time using $dbh->printProfile;.

With all that in place, run your script, watch the output and pass out lumps of coal accordingly. You might make use of all the time you saved to get ahead on your shopping!

Example output

=================================================================
7677 "SELECT *
      FROM employee
      WHERE UPPER(last_name) NOT LIKE 'KRINGLE'"   Total wall clock time: 0.0100
08s 
   execute ---------------------------------------
      Total
         Count        :         10
         Wall Clock   :  0.0066130 s    0.0006613 s
         Cpu Time     :  0.0000000 s    0.0000000 s
      returned 0E0
         Count        :         10
         Wall Clock   :  0.0066130 s    0.0006613 s
         Cpu Time     :  0.0000000 s    0.0000000 s
   fetchrow_hashref ---------------------------------------
      Total
         Count        :         58
         Wall Clock   :  0.0033950 s    0.0000585 s
         Cpu Time     :  0.0000000 s    0.0000000 s
      first
         Count        :         10
         Wall Clock   :  0.0010850 s    0.0001085 s
         Cpu Time     :  0.0000000 s    0.0000000 s
      no more rows
         Count        :         10
         Wall Clock   :  0.0004970 s    0.0000497 s
         Cpu Time     :  0.0000000 s    0.0000000 s
      normal
         Count        :         38
         Wall Clock   :  0.0018130 s    0.0000477 s
         Cpu Time     :  0.0000000 s    0.0000000 s