Tim Bunce wrote:
> Could you hack the nytprofhtml code to not show the source code
> and then send me the report? All it needs is:
>
> sub report_src_line {
> my ($value, undef, $linesrc, $profile, $subs, $calls, $thisfile) = @_;
>
> $linesrc = _escape_html($linesrc);
> + $linesrc = "#\n";
Done.
> Or (or preferably And) hack the incr_sub_inclusive_time() sub in NYTProf.xs
> like this:
>
> - if (trace_level >= 3)
> + if (trace_level >= 3 ||
> strEQ(SvPV_nolen(subname_sv),"Pkg::Subpkg::subname"))
>
> to see what the subroutine profiler is doing in relation to that sub.
Done+.
I've sent the results of this off list.
When running this before, I just scanned the top of the list and didn't look
further down. But when I got to editing the report to anonymize it, I noticed
the last subroutine in the list has a negative exclusive time equal in
magnitude to the exclusive time of the subroutine under discussion; the former
is called only by the latter. So, I did a second run after the first hack of
NYTProf.xs with this other subroutine traced as well; this is the version of
the incr_sub_inclusive_time() trace that you got (i.e. the report and the trace
are not for the same run).
If you can't tell, what I'm actually profiling is the primary test for the
module in question. The test processes a quite a bit of data.
Once I noticed interesting_negative_time_sub(), I started digging down. The
exclusive subroutine time in question is 422s. Further down the call tree
there's
"spent 202s making 232259 calls to Some::Moose::Object::new, avg 870µs/call"
the_weird_subroutine() does a bunch of setup before and cleanup after calling
interesting_negative_time_sub().
Basic structure of interesting_negative_time_sub():
... initialize ...
while ($TRUE) {
eval {
...
last if ...
next if ...
...
given (...) {
when (...) {
...
stuff that eventually results in 1 of the 232,259 Moose
objects
...
}
...
}
1;
}
or do {
...
}
}
...
> On Thu, Jul 02, 2009 at 09:20:18PM +0100, Tim Bunce wrote:
>> On Wed, Jul 01, 2009 at 07:43:01AM -0500, Elliot Shank wrote:
>>> Tim Bunce wrote:
>>>> All sounds odd. Are string evals or recursion involved?
>> Another thought... do any of the subs being called exit via exceptions?
>
> Or, more specifically, are any of the subs being called (by the sub with
> odd timings) xsubs that exit via an exception?
During the test, there are a couple of cases where an exception will be caught
by the eval above. None of those are from an xsubs or from Moose generated
methods (though they do come from methods on Moose objects).
--~--~---------~--~----~------------~-------~--~----~
You've received this message because you are subscribed to
the Devel::NYTProf Development User group.
Group hosted at: http://groups.google.com/group/develnytprof-dev
Project hosted at: http://perl-devel-nytprof.googlecode.com
CPAN distribution: http://search.cpan.org/dist/Devel-NYTProf
To post, email: [email protected]
To unsubscribe, email: [email protected]
-~----------~----~----~----~------~----~------~--~---
