Author: tim.bunce
Date: Fri Jul 3 08:35:13 2009
New Revision: 796
Modified:
trunk/Changes
trunk/NYTProf.xs
trunk/lib/Devel/NYTProf.pm
Log:
Fixed (rare) overflow bug for 32bit perls.
Fixed discarding of (rare) negative intervals.
Added log=F option to write trace log to a file.
Added sequence numbers to sub calls to aid debugging
Added sanity check warning for negative times from sub profiler
Modified: trunk/Changes
==============================================================================
--- trunk/Changes (original)
+++ trunk/Changes Fri Jul 3 08:35:13 2009
@@ -6,6 +6,10 @@
=head2 Changes in Devel::NYTProf 2.11
+XXX sysops needs docs and more ops
+
+ Fixed (rare) overflow bug for 32bit perls.
+ Fixed discarding of (rare) negative intervals.
Fixed risk of infinite recursion if trace enabled and
$SIG{__WARN__} was set to a code reference.
Fixed recursion depth measurement.
@@ -18,8 +22,8 @@
Added sysops=1 option which enables profiling of perl opcodes
that make potentially slow system calls. They appear as xsubs
in the current package with names prefixed by "CORE:".
-XXX needs docs and more ops
+ Added log=F option to write trace log to a file.
Added columns to the main source code reports to show
a count of sub calls and time spent in those calls.
Modified: trunk/NYTProf.xs
==============================================================================
--- trunk/NYTProf.xs (original)
+++ trunk/NYTProf.xs Fri Jul 3 08:35:13 2009
@@ -298,6 +298,7 @@
static Pid_t last_pid;
static NV cumulative_overhead_ticks = 0.0;
static NV cumulative_subr_secs = 0.0;
+static UV cumulative_subr_seqn = 0;
static unsigned int ticks_per_sec = 0; /* 0 forces error if not
set */
@@ -342,8 +343,9 @@
static FILE *logfh;
-void
+static void
logwarn(const char *pat, ...)
+ __attribute__format__(__printf__,1,2)
{
/* we avoid using any perl mechanisms here */
va_list args;
@@ -1721,8 +1723,7 @@
{
int saved_errno;
char *file;
- unsigned int elapsed;
- unsigned int overflow;
+ long elapsed, overflow;
if (!is_profiling || !profile_stmts) {
return;
@@ -1891,6 +1892,15 @@
if (strEQ(option, "file")) {
strncpy(PROF_output_file, value, MAXPATHLEN);
}
+ else if (strEQ(option, "log")) {
+ FILE *fp = fopen(value, "a");
+ if (!fp) {
+ logwarn("Can't open log file '%s' for writing: %s\n",
+ value, strerror(errno));
+ return;
+ }
+ logfh = fp;
+ }
else if (strEQ(option, "start")) {
if (strEQ(value,"begin")) profile_start = NYTP_START_BEGIN;
else if (strEQ(value,"init")) profile_start = NYTP_START_INIT;
@@ -2056,14 +2066,15 @@
typedef struct sub_call_start_st
{
- time_of_day_t sub_call_time;
+ time_of_day_t initial_call_time;
char fid_line[50];
SV *subname_sv;
AV *sub_av;
CV *sub_cv;
int call_depth;
- NV current_overhead_ticks;
- NV current_subr_secs;
+ NV initial_overhead_ticks;
+ NV initial_subr_secs;
+ UV seqn;
} sub_call_start_t;
static void
@@ -2075,9 +2086,9 @@
SV *incl_time_sv = *av_fetch(av, NYTP_SCi_INCL_RTIME, 1);
SV *excl_time_sv = *av_fetch(av, NYTP_SCi_EXCL_RTIME, 1);
/* statement overheads we've accumulated since we entered the sub */
- NV overhead_ticks = (int)(cumulative_overhead_ticks -
sub_call_start->current_overhead_ticks);
+ NV overhead_ticks = cumulative_overhead_ticks -
sub_call_start->initial_overhead_ticks;
/* seconds spent in subroutines called by this subroutine */
- NV called_sub_secs = (cumulative_subr_secs -
sub_call_start->current_subr_secs);
+ NV called_sub_secs = (cumulative_subr_secs -
sub_call_start->initial_subr_secs);
NV incl_subr_sec;
NV excl_subr_sec;
@@ -2087,26 +2098,26 @@
}
else {
time_of_day_t sub_end_time;
- unsigned int ticks, overflow;
+ long ticks, overflow;
/* calculate ticks since we entered the sub */
get_time_of_day(sub_end_time);
- get_ticks_between(sub_call_start->sub_call_time, sub_end_time,
ticks, overflow);
+ get_ticks_between(sub_call_start->initial_call_time, sub_end_time,
ticks, overflow);
incl_subr_sec = overflow + (ticks / (NV)ticks_per_sec);
/* subtract statement measurement overheads */
- incl_subr_sec -= (overhead_ticks / (NV)ticks_per_sec);
+ incl_subr_sec -= (overhead_ticks / ticks_per_sec);
/* exclusive = inclusive - time spent in subroutines called by
this subroutine */
excl_subr_sec = incl_subr_sec - called_sub_secs;
}
-
+
if (trace_level >= 3)
- logwarn(" <- %s after %"NVff"s incl - %"NVff"s = %"NVff"s excl
(sub %g-%g=%g, oh %g-%g=%gt) d%d @%s\n",
- SvPV_nolen(subname_sv), incl_subr_sec, called_sub_secs,
excl_subr_sec,
- cumulative_subr_secs, sub_call_start->current_subr_secs,
called_sub_secs,
- cumulative_overhead_ticks,
sub_call_start->current_overhead_ticks, overhead_ticks,
+ logwarn(" <- %s %"NVff"s excl = %"NVff"s incl - %"NVff"s
(%g-%g), oh %g-%g=%gt, d%d @%s #%lu\n",
+ SvPV_nolen(subname_sv), excl_subr_sec, incl_subr_sec,
called_sub_secs,
+ cumulative_subr_secs, sub_call_start->initial_subr_secs,
+ cumulative_overhead_ticks,
sub_call_start->initial_overhead_ticks, overhead_ticks,
(int)sub_call_start->call_depth,
- sub_call_start->fid_line);
+ sub_call_start->fid_line, sub_call_start->seqn);
/* only count inclusive time for the outer-most calls */
if (sub_call_start->call_depth <= 1) {
@@ -2235,9 +2246,10 @@
int saved_errno = errno;
if (!profile_stmts)
reinit_if_forked(aTHX);
- get_time_of_day(sub_call_start.sub_call_time);
- sub_call_start.current_overhead_ticks = cumulative_overhead_ticks;
- sub_call_start.current_subr_secs = cumulative_subr_secs;
+ get_time_of_day(sub_call_start.initial_call_time);
+ sub_call_start.initial_overhead_ticks = cumulative_overhead_ticks;
+ sub_call_start.initial_subr_secs = cumulative_subr_secs;
+ sub_call_start.seqn = ++cumulative_subr_seqn;
SETERRNO(saved_errno, 0);
}
@@ -2246,8 +2258,17 @@
* and returns the first op *within* the sub (typically a
nextstate/dbstate).
* for XS subs pp_entersub executes the entire sub
* and returns the op *after* the sub (PL_op->op_next)
+ * Other ops we profile (eg sysops) act like xsubs.
+ */
+ /* May croak (in xsub, in sysops, or in pp_entersub e.g., sub not
found).
+ * If it does croak then currently we don't record the call at all.
+ * Such cases are relatively rare, so it's not a significant problem.
+ * (The xsub case is probably the most significant, especially if the
+ * xsub calls back into perl code which then croaks. In that case the
+ * entersub to perl, and any calls made by the perl code, will get
recorded
+ * but the xsub call itself won't)
*/
- op = run_original_op(op_type); /* may croak */
+ op = run_original_op(op_type);
if (profile_sub_call) {
int saved_errno = errno;
@@ -2404,11 +2425,12 @@
sub_call_start.call_depth = (cv) ? CvDEPTH(cv)+(is_xs?1:0) : 1;
if (trace_level >= 2)
- fprintf(stderr, " ->%s %s from %d:%d (d%d, oh %gt, sub %gs)\n",
+ fprintf(stderr, " ->%s %s from %d:%d (d%d, oh %"NVff"t,
sub %"NVff"s) #%lu\n",
(is_xs) ? is_xs : " sub", subname_pv, fid, line,
sub_call_start.call_depth,
- sub_call_start.current_overhead_ticks,
- sub_call_start.current_subr_secs
+ sub_call_start.initial_overhead_ticks,
+ sub_call_start.initial_subr_secs,
+ sub_call_start.seqn
);
if (profile_subs) {
@@ -2916,6 +2938,7 @@
while (NULL != (sv = hv_iternextsv(fid_lines_hv, &fid_line_string,
&fid_line_len))) {
NV sc[NYTP_SCi_elements];
AV *av = (AV *)SvRV(sv);
+ int trace = (trace_level >= 3);
unsigned int fid = 0, line = 0;
(void)sscanf(fid_line_string, "%u:%u", &fid, &line);
@@ -2931,7 +2954,13 @@
sc[NYTP_SCi_REC_DEPTH] = output_uv_from_av(aTHX_ av,
NYTP_SCi_REC_DEPTH , 0) * 1.0;
output_str(sub_name, sub_name_len);
- if (trace_level >= 3)
+ /* sanity check - early warning */
+ if (sc[NYTP_SCi_INCL_RTIME] < 0.0 || sc[NYTP_SCi_EXCL_RTIME] <
0.0) {
+ logwarn("%s call has negative time!", sub_name);
+ trace = 1;
+ }
+
+ if (trace)
logwarn("%s called by %u:%u: count %"NVff" (i%"NVff"s
e%"NVff"s u%"NVff"s s%"NVff"s, d%"NVff" ri%"NVff"s)\n",
sub_name, fid, line, sc[NYTP_SCi_CALL_COUNT],
sc[NYTP_SCi_INCL_RTIME], sc[NYTP_SCi_EXCL_RTIME],
Modified: trunk/lib/Devel/NYTProf.pm
==============================================================================
--- trunk/lib/Devel/NYTProf.pm (original)
+++ trunk/lib/Devel/NYTProf.pm Fri Jul 3 08:35:13 2009
@@ -272,7 +272,13 @@
=head2 trace=N
-Set trace level to N. 0 is off (the default). Higher values cause more
detailed trace output.
+Set trace level to N. 0 is off (the default). Higher values cause more
detailed
+trace output. Trace output is written to STDERR or wherever the L</log=F>
+option has specified.
+
+=head2 log=F
+
+Specify the name of the file that L</trace=N> output should be written to.
=head2 start=...
--~--~---------~--~----~------------~-------~--~----~
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]
-~----------~----~----~----~------~----~------~--~---
