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

[Jon Schutz]

On Thu, 2007-10-11 at 22:39 +0100, Matt S Trout wrote:
> On Thu, Oct 11, 2007 at 10:17:13PM +0930, Jon Schutz wrote:
> > 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");
> > ...
> 
> Wouldn't it be better to have start_profile + end_profile methods?
> 
> There was a Catalyst::Plugin::Timer at one point proposed that did roughly
> that.
> 

I don't know what anyone else thinks, but IMHO having a single method
halves the number of lines of code for typical use cases. e.g. starting
with a big block of code where you just want to tag, say, 10 points and
see the timings, that's 10 calls to $c->profile().  With
start/end_profile, you'd need to add them in pairs, making 20 calls.  In
the other extreme, where you just want to get the timing of one section
of code, it's 2 calls either way.

> > 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.
> 
> Your patch isn't whitespace clean (you have whitespace only changes and
> mixed spaces and tabs in there), has no tests and isn't a diff -ur, so I can't
> actually tell whether it does anything sensible.
> 
> Try again please?
> 

Sure.  Perhaps you could point me in the right direction w.r.t. the
tests.  I couldn't see any existing test for the component timings that
I could add to.  Is there a representative test case there that captures
STDERR or log output and verifies its content, that I can use as a base?

> (Oh, and you want Catalyst::Model::DBIC::Schema::QueryLog - avoid the DBIC
> profiling plugins, they're all variously broken)
> 

Ta.

-- 

Jon