Grokbase
Topics Posts Groups | in
x
[ help ]

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

View Post | Saved ByFlat  Thread  Threaded | Next >
Jon [Catalyst-dev] Proposal for built-in profiling function
paperclip | +1 vote
saved to profiling by 1 person
[ Profile | Reply to group ] [ Flat  Thread  Threaded ]
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 _______________________________________________
Catalyst-dev mailing list
[email protected: Catalys...@lists.scsys.co.uk]
http://lists.scsys.co.uk/cgi-bin/mailman/listinfo/catalyst-dev

Attachment: profile-patch.txt

Thread : [Catalyst-dev] Proposal for built-in profiling function
1)
Jon That Catalyst reports the amount of time taken in each component method is very neat... but...
paperclip
2)
Matt S Trout Wouldn't it be better to have start_profile + end_profile methods? There was a...
3)
Jon I don't know what anyone else thinks, but IMHO having a single method halves the number of lines of...
4)
Matt S Trout Having a single method also makes it impossible to get nested graphs like we currently provide for...
5)
Jonathan Rockway Thanks! Applied as r7027 and r7028. In r7029, I changed your tabs to spaces to make the perl critic...
6)
Jonathan Rockway One other thing. Before your patch, the debugging output looks like: | Action | Time | |...
7)
Jon Hmmm, no the output was identical when I checked. I'll get a hold of svn trunk and have a look....
8)
Jon OK, sorry 'bout that; there's a bit of mucking around with UIDs which I suspect is unnecessary but...
paperclip
9)
Jonathan Rockway Hi Jon, applied as r7039. Thanks! Regards, Jonathan Rockway
spacer
View Post | Saved ByFlat  Thread  Threaded | Next >