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

[Matt S Trout]

On Fri, Oct 12, 2007 at 11:51:12AM +0930, Jon Schutz wrote:
> 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.

Having a single method also makes it impossible to get nested graphs like we
currently provide for forward() though.
 
> > > 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?

I'd write something that dug into $c->stats at request-end.

I do wonder if with a bit of work you couldn't make $c->stats a subclass of
a tree and provide an API that -any- profiling code could attach itself to
without needing a plugin. Adding methods to core still feels like it's
unnecessary though I've not poked around in detail as to alternatives.

-- 
      Matt S Trout       Need help with your Catalyst or DBIx::Class project?
   Technical Director                    http://www.shadowcat.co.uk/catalyst/
 Shadowcat Systems Ltd.  Want a managed development or deployment platform?
http://chainsawblues.vox.com/            http://www.shadowcat.co.uk/servers/