Author: tim.bunce
Date: Sun Jul 5 15:31:26 2009
New Revision: 804
Modified:
trunk/NYTProf.xs
trunk/lib/Devel/NYTProf.pm
trunk/lib/Devel/NYTProf/Core.pm
Log:
Switched to using context stack offsets instead of pointers to track current
sub enter and chain of outer callers. A step on the way to at least
detecting
xsubs & builtins that exit via exceptions.
Record calling fid and line before invoking the op.
Added docs describing how the subroutine profiler works.
Modified: trunk/NYTProf.xs
==============================================================================
--- trunk/NYTProf.xs (original)
+++ trunk/NYTProf.xs Sun Jul 5 15:31:26 2009
@@ -1206,7 +1206,7 @@
if (trace_level >= 4) {
if (found)
logwarn("fid %d: %.*s\n", found->id, found->key_len,
found->key);
- else logwarn("fid -: %.*s HAS NO FID\n", entry.key_len,
entry.key);
+ else logwarn("fid -: %.*s not profiled\n", entry.key_len,
entry.key);
}
return (found) ? found->id : 0;
}
@@ -2067,7 +2067,7 @@
typedef struct subr_entry_st subr_entry_t;
struct subr_entry_st {
time_of_day_t initial_call_time;
- int calling_fid;
+ unsigned int calling_fid;
int calling_line;
SV *subname_sv;
AV *sub_av;
@@ -2076,9 +2076,14 @@
NV initial_overhead_ticks;
NV initial_subr_secs;
UV seqn;
- subr_entry_t *caller;
+ int caller_ix;
+ /* ensure all items are initialized in pp_subcall_profiler */
};
-static subr_entry_t *subr_entry_latest;
+static int subr_entry_latest_ix;
+
+/* return the subr_entry_t of the caller of the specified subr_entry_t */
+#define subr_entry_caller(subr_entry) ((subr_entry &&
subr_entry->caller_ix) \
+ ? SSPTR(subr_entry->caller_ix, subr_entry_t *) : NULL)
static void
incr_sub_inclusive_time(pTHX_ subr_entry_t *subr_entry)
@@ -2140,7 +2145,7 @@
if (subr_entry->subname_sv)
sv_free(subr_entry->subname_sv);
- subr_entry_latest = subr_entry->caller;
+ subr_entry_latest_ix = subr_entry->caller_ix;
cumulative_subr_secs += excl_subr_sec;
SETERRNO(saved_errno, 0);
@@ -2263,9 +2268,15 @@
subr_entry->initial_subr_secs = cumulative_subr_secs;
subr_entry->seqn = ++cumulative_subr_seqn;
- /* link in as head of the chain */
- subr_entry->caller = subr_entry_latest;
- subr_entry_latest = subr_entry;
+ char *file = OutCopFILE(prev_cop);
+ subr_entry->calling_fid = (file == last_executed_fileptr)
+ ? last_executed_fid
+ : get_file_id(aTHX_ file, strlen(file), NYTP_FIDf_VIA_SUB);
+ subr_entry->calling_line = CopLINE(prev_cop);
+
+ /* link in as head of the chain, but use offset not pointer */
+ subr_entry->caller_ix = subr_entry_latest_ix;
+ subr_entry_latest_ix = save_ix;
/* sub name related items */
subr_entry->subname_sv = &PL_sv_undef;
@@ -2298,13 +2309,10 @@
/* get line, file, and fid for statement *before* the call */
- char *file = OutCopFILE(prev_cop);
- unsigned int fid;
/* XXX could use same closest_cop as DB_stmt() but it doesn't seem
* to be needed here. Line is 0 only when call is from embedded
* C code like mod_perl (at least in my testing so far)
*/
- int line = CopLINE(prev_cop);
char fid_line_key[50];
int fid_line_key_len;
SV *subname_sv = newSV(0);
@@ -2388,13 +2396,6 @@
if (is_xs && *subname_pv == 'D' && strEQ(subname_pv, "DB::_INIT"))
goto skip_sub_profile;
- fid = (file == last_executed_fileptr)
- ? last_executed_fid
- : get_file_id(aTHX_ file, strlen(file), NYTP_FIDf_VIA_SUB);
- fid_line_key_len = sprintf(fid_line_key, "%u:%d", fid, line);
- subr_entry->calling_fid = fid;
- subr_entry->calling_line = line;
-
/* { called_subname => { "fid:line" => [ count, incl_time ] } } */
sv_tmp = *hv_fetch(sub_callers_hv, subname_pv,
(I32)SvCUR(subname_sv), 1);
@@ -2435,6 +2436,9 @@
}
}
+ fid_line_key_len = sprintf(fid_line_key, "%u:%d",
+ subr_entry->calling_fid, subr_entry->calling_line);
+
/* drill-down to array of sub call information for this
fid_line_key */
sv_tmp = *hv_fetch((HV*)SvRV(sv_tmp), fid_line_key,
fid_line_key_len, 1);
if (!SvROK(sv_tmp)) { /* first call from this fid:line - autoviv
array ref */
@@ -2455,16 +2459,18 @@
* have already left the sub, unlike the non-xs case. */
subr_entry->call_depth = (cv) ? CvDEPTH(cv)+(is_xs?1:0) : 1;
- if (trace_level >= 2)
+ if (trace_level >= 2) {
+ subr_entry_t *se_caller = subr_entry_caller(subr_entry);
fprintf(stderr, " ->%s %s from %s %d:%d (d%d, oh %"NVff"t,
sub %"NVff"s) #%lu\n",
(is_xs) ? is_xs : " sub", subname_pv,
- (subr_entry->caller) ?
SvPV_nolen(subr_entry->caller->subname_sv) : "",
- fid, line,
+ (se_caller) ? SvPV_nolen(se_caller->subname_sv) : "",
+ subr_entry->calling_fid, subr_entry->calling_line,
subr_entry->call_depth,
subr_entry->initial_overhead_ticks,
subr_entry->initial_subr_secs,
subr_entry->seqn
);
+ }
if (profile_subs) {
subr_entry->subname_sv = subname_sv;
Modified: trunk/lib/Devel/NYTProf.pm
==============================================================================
--- trunk/lib/Devel/NYTProf.pm (original)
+++ trunk/lib/Devel/NYTProf.pm Sun Jul 5 15:31:26 2009
@@ -793,6 +793,6 @@
added zip compression. Jan Dubois contributed Windows support.
Adam's work is sponsored by The New York Times Co.
L<http://open.nytimes.com>.
-Tim's work was partly sponsored by Shopzilla. L<http://www.shopzilla.com>.
+Tim's work was partly sponsored by Shopzilla L<http://www.shopzilla.com>
during 2008.
=cut
Modified: trunk/lib/Devel/NYTProf/Core.pm
==============================================================================
--- trunk/lib/Devel/NYTProf/Core.pm (original)
+++ trunk/lib/Devel/NYTProf/Core.pm Sun Jul 5 15:31:26 2009
@@ -39,16 +39,100 @@
This module is not meant to be used directly.
See L<Devel::NYTProf>, L<Devel::NYTProf::Data>, and
L<Devel::NYTProf::Reader>.
+While it's not meant to be used directly, it is a handy place to document
some
+internals.
+
+=head1 SUBROUTINE PROFILER
+
+The subroutine profiler intercepts the C<entersub> opcode which perl uses
to
+invoke a subroutine, both XS subs (henceforth xsubs) and pure perl subs.
+
+The following sections outline the way the subroutine profiler works:
+
+=head2 Before the subroutine call
+
+The profiler records the current time, the current value of
+cumulative_subr_secs (as initial_subr_secs), and the current
+cumulative_overhead_ticks (as initial_overhead_ticks).
+
+The statement profiler measures time at the start and end of processing for
+each statement (so time spent in the profiler, writing to the file for
example,
+is excluded.) It accumulates the measured overhead into the
+cumulative_overhead_ticks variable.
+
+In a similar way, the subroutine profiler measures the I<exclusive> time
spent
+in subroutines and accumulates it into the cumulative_subr_secs global.
+
+=head2 Make the subroutine call
+
+The call is made by executing the original perl internal code for the
+C<entersub> opcode.
+
+=head3 Calling a perl subroutine
+
+If the sub being called is a perl sub then when the entersub opcode
returns,
+back into the subroutine profiler, the subroutine has been 'entered' but
the
+first opcode of the subroutine hasn't been executed yet.
+Crucially though, a new scope has been entered by the entersub opcode.
+
+The subroutine profiler then pushes a destructor onto the context stack.
+The destructor is effectively I<inside> the sub, like a C<local>, and so
will be
+triggered when the subroutine exits by I<any> means. When the destructor
is
+invoked it calls a function which completes the measurement of the time
spent
+in the sub.
+
+In this way the profiling of perl subroutines is very accurate and robust.
+
+=head3 Calling an xsub
+
+If the sub being called is an xsub, then control doesn't return from the
+entersub opcode until the xsub has returned. The profiler detects this and
+calls the function which completes the measurement of the time spent in the
+xsub.
+
+So far so good, but there's a problem. What if the xsub doesn't return
normally
+but throws an exception instead?
+
+In that case (currently) the profiler acts as if the xsub was never called.
+Time spent inside the xsub will be allocated to the calling sub.
+
+=head2 Completing the measurement
+
+The function which completes the timing of a subroutine call does the
following:
+
+It calculates the time spent in the statement profiler:
+
+ overhead_ticks = cumulative_overhead_ticks - initial_overhead_ticks
+
+and subtracts that from the total time spent 'inside' the subroutine:
+
+ incl_subr_sec = (time now - time call was made) - overhead_ticks
+
+That gives us an accurate I<inclusive> time. To get the I<exclusive> time
+it calculates the time spent in subroutines called from the subroutine call
+we're measuring:
+
+ called_sub_secs = cumulative_subr_secs - initial_subr_secs
+
+and subtracts that from the incl_subr_sec:
+
+ excl_subr_sec = incl_subr_sec - called_sub_secs
+
+To make that easier to follow, consider a call to a sub that calls no
others.
+In that case cumulative_subr_secs remains unchanged during the call, so
+called_sub_secs is zero, and excl_subr_sec is the same as incl_subr_sec.
+
+Finally, it adds the exclusive time to the cumulative exclusive time:
+
+ cumulative_subr_secs += excl_subr_sec
+
=head1 AUTHOR
-B<Adam Kaplan>, C<< <akaplan at nytimes.com> >>
B<Tim Bunce>, L<http://www.tim.bunce.name> and L<http://blog.timbunce.org>
-B<Steve Peters>, C<< <steve at fisharerojo.org> >>
=head1 COPYRIGHT AND LICENSE
- Copyright (C) 2008 by Adam Kaplan and The New York Times Company.
- Copyright (C) 2008 by Tim Bunce.
+ Copyright (C) 2008, 2009 by Tim Bunce.
This library is free software; you can redistribute it and/or modify
it under the same terms as Perl itself, either Perl version 5.8.8 or,
--~--~---------~--~----~------------~-------~--~----~
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]
-~----------~----~----~----~------~----~------~--~---
