Profile Your Catalyst/DBIC App with QueryLog
Months ago I implemented DBIx::Class::Storage::Statistics with the intent of making some sort of profiling tool. I finally got off my ass and did it. DBIx::Class::QueryLog should be on CPAN this weekend.
At $work we are replacing a legacy system with one based on Catalyst. One of the deliverables for this year is a new order entry application. Since our customer service folks are used to working in a terminal based system speed is of great concern to us.
So I installed DBIx::Class::QueryLog as the debugobj as described in it’s documentation, dropped it in the stash and added some code to our wrapper.tmpl:
[% IF querylog %]
Query Log Report
[% SET total = querylog.timeelapsed | format('%0.6f') %]
Total SQL Time: [% total | format('%0.6f') %] seconds
[% SET qcount = querylog.count %]
Total Queries: [% qcount %]
[% IF qcount %]
Avg Statement Time: [% (querylog.timeelapsed / qcount) | format('%0.6f') %] seconds.
5 Slowest Queries
Time
%
SQL
[% SET i = 0 %]
[% FOREACH q = querylog.getsortedqueries %]
[% q.timeelapsed | format('%0.6f') %]
[% ((q.time elapsed / total ) * 100 ) | format('%i') %]%
[% q.sql %]
[% IF i == 5 %]
[% LAST %]
[% END %]
[% SET i = i + 1 %]
[% END %]
[% END %]
[% END %]
The first run yielded this:
Well. That select from users could use an index on username, eh?
Weee! That one disappeared. What are all these role selections? We use Catalyst::Plugin::Authorization::Roles but this looks fishy. We might could use an index on the role name but there are only 6 rows in that table. A bit more investigation finds a loop in our Root controller that iterates over a set of roles calling checkuserroles() to try and find out where we should redirect the user. So lets swap that out for creating an array of roles and using grep…
Kick ass! We are down to two measly queries. We reduced the number of queries by about 75% and decreased the time spent executing SQL by about 75% as well. These queries were being executed on every page load.
UPDATE:Yeah, the average statement time was broken during that. Oops.
Comments (2 comments)
looking forward to it ;-)
jatan / March 2nd, 2007, 4:01 am / #
[...] Tailing error_log on 3 webservers isn’t as much fun as the kids make it out to be! My work on DBIx::Class::QueryLog has me in the mode of providing performance information in the footer of [...]
One Mo’ Gin - Sometimes Once Isn’t Enough » Archives » Adding Action Timings To Your Output / May 18th, 2007, 8:36 am / #
Post a comment