jon+catalyst at youramigo
Oct 15, 2007, 6:34 PM
Post #5 of 10
(2318 views)
Permalink
|
|
Re: Proposal for built-in profiling function
[In reply to]
|
|
On Fri, 2007-10-12 at 18:45 +0100, Matt S Trout wrote:
> 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.
>
I've created Catalyst::Stats and factored out the embedded stats code in
Catalyst.pm. Default functionality is identical to existing. Anybody
can substitute their own class with
__PACKAGE__->stats_class("My::Stats"). $c->stats returns the stats
object. Thus typical use is $c->stats->profile(...). The profile
method can take a single comment or multiple args to mark begin/end so
fits both use cases discussed above.
Importantly, stats can be enabled without having to enable debug,
through the normal mechanisms - use Catalyst qw/-Stats=1/,
CATALYST_STATS=1. When disabled, overhead is negligible.
Patch against Catalyst-Runtime-5.7010 is attached, inc doc and tests.
Perldoc provided below for convenience.
Regards,
--
Jon
==================================
NAME
Catalyst::Stats - Catalyst Timing Statistics Class
SYNOPSIS
$stats = $c->stats;
$stats->enable(1);
$stats->profile($comment);
$stats->profile(begin => $block_name, comment =>$comment);
$stats->profile(end => $block_name);
$elapsed = $stats->elapsed;
$report = $stats->report;
See Catalyst.
DESCRIPTION
This module provides the default, simple timing stats collection functionality for
Catalyst. If you want something different set "MyApp->stats_class" in your applica-
tion module, e.g.:
__PACKAGE__->stats_class( "My::Stats" );
If you write your own, your stats object is expected to provide the interface
described here.
Catalyst uses this class to report timings of component actions. You can add profil-
ing points into your own code to get deeper insight. Typical usage might be like this:
sub mysub {
my ($c, ...) = @_;
$c->stats->profile(begin => "mysub");
# code goes here
...
$c->stats->profile("starting critical bit");
# code here too
...
$c->stats->profile("completed first part of critical bit");
# more code
...
$c->stats->profile("completed second part of critical bit");
# more code
...
$c->stats->profile(end => "mysub");
}
Supposing mysub was called from the action "process" inside a Catalyst Controller
called "service", then the reported timings for the above example might look something
like this:
.----------------------------------------------------------------+-----------.
│ Action │ Time │
+----------------------------------------------------------------+-----------+
│ /service/process │ 1.327702s │
│ mysub │ 0.555555s │
│ - starting critical bit │ 0.111111s │
│ - completed first part of critical bit │ 0.333333s │
│ - completed second part of critical bit │ 0.111000s │
│ /end │ 0.000160s │
’----------------------------------------------------------------+-----------’
which means mysub took 0.555555s overall, it took 0.111111s to reach the critical bit,
the first part of the critical bit took 0.333333s, and the second part 0.111s.
METHODS
new
Constructor.
$stats = Catalyst::Stats->new;
enable
$stats->enable(0);
$stats->enable(1);
Enable or disable stats collection. By default, stats are enabled after object cre-
ation.
profile
$stats->profile($comment);
$stats->profile(begin => $block_name, comment =>$comment);
$stats->profile(end => $block_name);
Marks a profiling point. These can appear in pairs, to time the block of code between
the begin/end pairs, or by themselves, in which case the time of execution to the pre-
vious profiling point will be reported.
The argument may be either a single comment string or a list of name-value pairs.
Thus the following are equivalent:
$stats->profile($comment);
$stats->profile(comment => $comment);
The following key names/values may be used:
* begin => ACTION
Marks the beginning of a block. The value is used in the description in the tim-
ing report.
* end => ACTION
Marks the end of the block. The name given must match a previous ’begin’. Cor-
rect nesting is recommended, although this module is tolerant of blocks that are
not correctly nested, and the reported timings should accurately reflect the time
taken to execute the block whether properly nested or not.
* comment => COMMENT
Comment string; use this to describe the profiling point. It is combined with the
block action (if any) in the timing report description field.
* uid => UID
Assign a predefined unique ID. This is useful if, for whatever reason, you wish
to relate a profiling point to a different parent than in the natural execution
sequence.
* parent => UID
Explicitly relate the profiling point back to the parent with the specified UID.
rect nesting is recommended, although this module is tolerant of blocks that are
not correctly nested, and the reported timings should accurately reflect the time
taken to execute the block whether properly nested or not.
* comment => COMMENT
Comment string; use this to describe the profiling point. It is combined with the
block action (if any) in the timing report description field.
* uid => UID
Assign a predefined unique ID. This is useful if, for whatever reason, you wish
to relate a profiling point to a different parent than in the natural execution
sequence.
* parent => UID
Explicitly relate the profiling point back to the parent with the specified UID.
The profiling point will be ignored if the UID has not been previously defined.
Returns the UID of the current point in the profile tree. The UID is automatically
assigned if not explicitly given.
elapsed
$elapsed = $stats->elapsed
Get the total elapsed time (in seconds) since the object was created.
report
print $stats->report ."\n";
$report = $stats->report;
@report = $stats->report;
In scalar context, generates a textual report. In array context, returns the array of
results where each row comprises:
[ depth, description, time, rollup ]
The depth is the calling stack level of the profiling point.
The description is a combination of the block name and comment.
The time reported for each block is the total execution time for the block, and the
time associated with each intermediate profiling point is the elapsed time from the
previous profiling point.
The ’rollup’ flag indicates whether the reported time is the rolled up time for the
block, or the elapsed time from the previous profiling point.
SEE ALSO
Catalyst.
AUTHOR
Jon Schutz
COPYRIGHT
This program is free software, you can redistribute it and/or modify it under the same
terms as Perl itself.
perl v5.8.8 Catalyst-Runtime-5.7010::lib::Catalyst::Stats(3)
|
profile-patch.txt
signature.asc
