view release on metacpan or  search on metacpan

lib/Devel/NYTProf.pm  view on Meta::CPAN

=head1 DATA COLLECTION AND INTERPRETATION

NYTProf tries very hard to gather accurate information.  The nature of the
internals of perl mean that, in some cases, the information that's gathered is
accurate but surprising. In some cases it can appear to be misleading.
(Of course, in some cases it may actually be plain wrong. Caveat lector.)

=head2 If Statement and Subroutine Timings Don't Match

NYTProf has two profilers: a statement profiler that's invoked when perl moves
from one perl statement to another, and a subroutine profiler that's invoked
when perl calls or returns from a subroutine.

The individual statement timings for a subroutine usually add up to slightly
less than the exclusive time for the subroutine. That's because the handling of
the subroutine call and return overheads is included in the exclusive time for
the subroutine. The difference may only be a few microseconds but that may
become noticeable for subroutines that are called hundreds of thousands of times.

The statement profiler keeps track how much time was spent on overheads, like
writing statement profile data to disk. The subroutine profiler subtracts the
overheads that have accumulated between entering and leaving the subroutine in
order to give a more accurate profile.  The statement profiler is generally
very fast because most writes get buffered for zip compression so the profiler
overhead per statement tends to be very small, often a single 'tick'.
The result is that the accumulated overhead is quite noisy. This becomes more
significant for subroutines that are called frequently and are also fast.
This may be another, smaller, contribution to the discrepancy between statement
time and exclusive times.

=head2 If Headline Subroutine Timings Don't Match the Called Subs

Overall subroutine times are reported with a headline like C<spent 10s (2+8) within ...>.
In this example, 10 seconds were spent inside the subroutine (the "inclusive
time") and, of that, 8 seconds were spent in subroutines called by this one.
That leaves 2 seconds as the time spent in the subroutine code itself (the
"exclusive time", sometimes also called the "self time").

The report shows the source code of the subroutine. Lines that make calls to
other subroutines are annotated with details of the time spent in those calls.

Sometimes the sum of the times for calls made by the lines of code in the
subroutine is less than the inclusive-exclusive time reported in the headline
(10-2 = 8 seconds in the example above).

What's happening here is that calls to other subroutines are being made but
NYTProf isn't able to determine the calling location correctly so the calls
don't appear in the report in the correct place.

Using an old version of perl is one cause (see below). Another is calling
subroutines that exit via C<goto &sub;> - most frequently encountered in
AUTOLOAD subs and code using the L<Memoize> module.

In general the overall subroutine timing is accurate and should be trusted more
than the sum of statement or nested sub call timings.

=head2 Perl 5.10.1+ (or else 5.8.9+) is Recommended

These versions of perl yield much more detailed information about calls to
BEGIN, CHECK, INIT, and END blocks, the code handling tied or overloaded
variables, and callbacks from XS code.

Perl 5.12 will hopefully also fix an inaccuracy in the timing of the last
statement and the condition clause of some kinds of loops:
L<http://rt.perl.org/rt3/Ticket/Display.html?id=60954>

=head2 eval $string

Perl treats each execution of a string eval (C<eval $string;> not C<eval { ...  }>)
as a distinct file, so NYTProf does as well. The 'files' are given names with
this structure:

	(eval $sequence)[$filename:$line]

for example "C<(eval 93)[/foo/bar.pm:42]>" would be the name given to the
93rd execution of a string eval by that process and, in this case, the 93rd
eval happened to be one at line 42 of "/foo/bar.pm".

Nested string evals can give rise to file names like

	(eval 1047)[(eval 93)[/foo/bar.pm:42]:17]

=head3 Merging Evals

Some applications execute a great many string eval statements. If NYTProf generated
a report page for each one it would not only slow report generation but also
make the overall report less useful by scattering performance data too widely.
On the other hand, being able to see the actual source code executed by an
eval, along with the timing details, is often I<very> useful.

To try to balance these conflicting needs, NYTProf currently I<merges
uninteresting string eval siblings>.

What does that mean? Well, for each source code line that executed any string
evals, NYTProf first gathers the corresponding eval 'files' for that line
(known as the 'siblings') into groups keyed by distinct source code.

Then, for each of those groups of siblings, NYTProf will 'merge' a group
that shares the same source code and doesn't execute any string evals itself.
Merging means to pick one sibling as the survivor and merge and delete all
the data from the others into it.

If there are a large number of sibling groups then the data for all of them are
merged into one regardless.

The report annotations will indicate when evals have been merged together.

=head3 Merging Anonymous Subroutines

Anonymous subroutines defined within string evals have names like this:

	main::__ANON__[(eval 75)[/foo/bar.pm:42]:12]

That anonymous subroutine was defined on line 12 of the source code executed by
the string eval on line 42 of F</foo/bar.pm>. That was the 75th string eval
executed by the program.

Anonymous subroutines I<defined on the same line of sibling evals that get
merged> are also merged. That is, the profile information is merged into
one and the others are discarded.

lib/Devel/NYTProf.pm  view on Meta::CPAN

To speed up L<nytprofhtml> try using the --minimal (-m) or --no-flame options.

=head1 REPORTS

The L<Devel::NYTProf::Data> module provides a low-level interface for loading
the profile data.

The L<Devel::NYTProf::Reader> module provides an interface for generating
arbitrary reports.  This means that you can implement your own output format in
perl. (Though the module is in a state of flux and may be deprecated soon.)

Included in the bin directory of this distribution are some scripts which
turn the raw profile data into more useful formats:

=head2 nytprofhtml

Creates attractive, richly annotated, and fully cross-linked html
reports (including statistics, source code and color highlighting).
This is the main report generation tool for NYTProf.

=head2 nytprofcg

Translates a profile into a format that can be loaded into KCachegrind
L<http://kcachegrind.github.io/>

=head2 nytprofcalls

Reads a profile and processes the calls events it contains.

=head2 nytprofmerge

Reads multiple profile data files and writes out a new file containing the merged profile data.

=head1 LIMITATIONS

=head2 Threads and Multiplicity

C<Devel::NYTProf> is not currently thread safe or multiplicity safe.
If you'd be interested in helping to fix that then please get in
touch with us. Meanwhile, profiling is disabled when a thread is created, and
NYTProf tries to ignore any activity from perl interpreters other than the
first one that loaded it.

=head2 Coro

The C<Devel::NYTProf> subroutine profiler gets confused by the stack gymnastics
performed by the L<Coro> module and aborts. When profiling applications that
use Coro you should disable the subroutine profiler using the L</subs=0> option.

=head2 FCGI::Engine

Using C<open('-|')> in code running under L<FCGI::Engine> causes a panic in nytprofcalls.
See https://github.com/timbunce/devel-nytprof/issues/20 for more information.

=head2 For perl < 5.8.8 it may change what caller() returns

For example, the L<Readonly> module croaks with "Invalid tie" when profiled with
perl versions before 5.8.8. That's because L<Readonly> explicitly checking for
certain values from caller(). The L<NEXT> module is also affected.

=head2 For perl < 5.10.1 it can't see some implicit calls and callbacks

For perl versions prior to 5.8.9 and 5.10.1, some implicit subroutine calls
can't be seen by the I<subroutine> profiler. Technically this affects calls
made via the various perl C<call_*()> internal APIs.

For example, BEGIN/CHECK/INIT/END blocks, the C<TIE>I<whatever> subroutine
called by C<tie()>, all calls made via operator overloading, and callbacks from
XS code, are not seen.

The effect is that time in those subroutines is accumulated by the
subs that triggered the call to them. So time spent in calls invoked by
perl to handle overloading are accumulated by the subroutines that trigger
overloading (so it is measured, but the cost is dispersed across possibly many
calling locations).

Although the calls aren't seen by the subroutine profiler, the individual
I<statements> executed by the code in the called subs are profiled by the
statement profiler.

=head2 #line directives

The reporting code currently doesn't handle #line directives, but at least it
warns about them. Patches welcome.

=head2 Freed values in @_ may be mutated

Perl has a class of bugs related to the fact that values placed in the stack
are not reference counted. Consider this example:

  @a = (1..9);  sub s { undef @a; print $_ for @_ }  s(@a);

The C<undef @a> frees the values that C<@_> refers to. Perl can sometimes
detect when a freed value is accessed and treats it as an undef. However, if
the freed value is assigned some new value then @_ is effectively corrupted.

NYTProf allocates new values while it's profiling, in order to record program
activity, and so may appear to corrupt C<@_> in this (rare) situation.  If this
happens, NYTProf is simply exposing an existing problem in the code.

=head2 Lvalue subroutines aren't profiled when using use_db_sub=1

Currently 'lvalue' subroutines (subs that can be assigned to, like C<foo() =
42>) are not profiled when using use_db_sub=1.

=head1 CLOCKS

Here we discuss the way NYTProf gets high-resolution timing information from
your system and related issues.

=head2 POSIX Clocks

These are the clocks that your system may support if it supports the POSIX
C<clock_gettime()> function. Other clock sources are listed in the
L</Other Clocks> section below.

The C<clock_gettime()> interface allows clocks to return times to nanosecond
precision. Of course few offer nanosecond I<accuracy> but the extra precision
helps reduce the cumulative error that naturally occurs when adding together
many timings. When using these clocks NYTProf outputs timings as a count of 100
nanosecond ticks.

=head3 CLOCK_MONOTONIC

CLOCK_MONOTONIC represents the amount of time since an unspecified point in
the past (typically system start-up time).  It increments uniformly
independent of adjustments to 'wallclock time'. NYTProf will use this clock by
default, if available.