[Catalyst-dev] Proposal for built-in profiling function

Jon Schutz jon+catalyst at youramigo.com
Thu Oct 11 13:47:13 GMT 2007


That Catalyst reports the amount of time taken in each component method
is very neat... but restrictive.  It would be nice to easily add
"profile points" into the code and have the execution time to those
points reported as well.

The idea is that the summary report which currently looks something like
this:

.----------------------------------------------------------------+-----------.
| Action                                                         | Time      |
+----------------------------------------------------------------+-----------+
| /status/auto                                                   | 0.000751s |
| /status/syncstatus                                             | 0.241494s |
| /end                                                           | 0.065917s |
|  -> SLx::View::TT->process                                     | 0.064111s |
'----------------------------------------------------------------+-----------'

with scatterings of code like this:

$c->profile("starting long routine");
...
$c->profile("done stuff");
...

might turn the resulting report into this:

.----------------------------------------------------------------+-----------.
| Action                                                         | Time      |
+----------------------------------------------------------------+-----------+
| /status/auto                                                   | 0.000751s |
| /status/syncstatus                                             | 0.241494s |
|   starting long routine                                        | 0.000213s |
|   done stuff                                                   | 0.221234s |
| /end                                                           | 0.065917s |
|  -> SLx::View::TT->process                                     | 0.064111s |
'----------------------------------------------------------------+-----------'

where each reported time for a profile point is the time since the
previous profile point or the beginning of the execution of the
component.

I tried using Devel::Profile and a couple similar modules, but Catalyst
died (in View::TT) on startup.  The reason for this wasn't clear, but I
didn't try that hard to work it out because that type of profiler gives
me timings to a subroutine level, but I really wanted to put profile
points through arbitrary bits of code with ease.
C::P::DBIC::Schema::Profiler is also useful, but only for DBIx::Class
models.

So I started writing a plugin to do this (yes, a plugin, because it
needed the request start time), but realised that I would have to
either:

- have a profiling mechanism separate from the core, which would have to
duplicate functionality already in the core, or 

- append to the mechanism in the core, requiring that the plugin mess
with internals of the core

... neither of which were entirely satisfactory.

So, I'd like to propose a trivial change to the core code to allow this
functionality.  Basically it just adds a 'profile' method which hooks
into the existing timing tree.  I've been running this code and found it
enormously useful in isolating problem areas.  Patch for Catalyst.pm
against 5.7010 is attached.

-- 

Jon 


-------------- next part --------------
A non-text attachment was scrubbed...
Name: profile-patch.txt
Type: text/x-patch
Size: 2783 bytes
Desc: not available
Url : http://lists.scsys.co.uk/pipermail/catalyst-dev/attachments/20071011/6128e72e/profile-patch.bin


More information about the Catalyst-dev mailing list