Adding Action Timings To Your Output
UPDATE: Jon Schutz recently posted an update to this idea. Please use his!
When handing a request Catalyst politely outputs each action executed (in order) along with it’s timings, like so:
2007/05/17 13:52:18 INFO [Catalyst : 1506] Request took 0.429198s (2.330/s) .----------------------------------------------------------------+-----------. | Action | Time | +----------------------------------------------------------------+-----------+ | /auto | 0.102865s | | /default | 0.040768s | | -> /search/default | 0.028275s | | /end | 0.171297s | | -> Greenspan::Lockhart::View::TT->process | 0.165873s | '----------------------------------------------------------------+-----------'
This information is helpful when trying to trace the flow of execution, find an error or when trying to isolate which action is hindering speedy throughput. But what does one do when multiple people are using a load-balanced app simulataneously? 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 the page. So I set out to do the same for Catalyst actions.
Turns out this is easier than it sounds. Catalyst keeps a Tree::Simple object in $c->stats() that details execution. Each node is a hashref containing (at minimum) ‘action’ and ‘elapsed’ keys. The former being the name of the action and the latter being how long it took to execute. Oddly, that latter value is not a plain number, but a float followed by an ’s’ to denote it is in seconds.
A quick snippet of code placed into the ‘end’ of my root controller can digest this tree and produce something useful for my templates:
my $tree = $c->stats();
my $dvisit = new Tree::Simple::Visitor();
$tree->accept($dvisit);
$c->stash->{’actionstats’} = $dvisit->getResults();
The value of the ‘actionstats’ key is now an array of hashrefs representing each action in the chain in execution order. A simple FOREACH and we’ve got ourselves a list of actions with their timings.
The actions could be arranged in order of time elapsed using Tree::Simple::Vistitor::Sort, but I personally prefer execution order. YMMV.
Comments (One comment)
[...] a year ago, onemogin wrote an article on adding action timings to the HTML output of a Catalyst app. To do so, it was necessary to access $c->stats, which at the time was an internal object (that [...]
All Notes Technical » Adding Action Timings to your Catalyst Output / April 19th, 2008, 9:22 am / #
Post a comment