Author: tim.bunce
Date: Mon Oct 20 05:17:13 2008
New Revision: 528
Added:
trunk/t/test70-subexcl.p
Modified:
trunk/HACKING
trunk/MANIFEST
trunk/NYTProf.xs
trunk/lib/Devel/NYTProf.pm
Log:
Adjust trace levels slightly, mainly moving new fids and subs up to level 2.
Be more paranoid about arith overflow etc in sub timing code.
Add note re a possible bug/limitation in the HACKING file.
Update the docs re inclusive timing of recursive subs.
Modified: trunk/HACKING
==============================================================================
--- trunk/HACKING (original)
+++ trunk/HACKING Mon Oct 20 05:17:13 2008
@@ -298,3 +298,6 @@
Could add ::Data method to write source code for each fid into
$dir/nytprof_src_$fid.txt
OR, probably better, add method to return source code array ref, that
defaults to returning
the embeded source array, if available, else hunts for and loads current
source file.
+
+Bug or limitation?: sub calls in a continue { ... } block of a while () get
+associated with the 'next;' within the loop.
Modified: trunk/MANIFEST
==============================================================================
--- trunk/MANIFEST (original)
+++ trunk/MANIFEST Mon Oct 20 05:17:13 2008
@@ -91,6 +91,7 @@
t/test50-disable.x
t/test60-subname.p
t/test60-subname.rdt
+t/test70-subexcl.p
t/test80-recurs.p
t/test80-recurs.rdt
t/test90-stress.p
Modified: trunk/NYTProf.xs
==============================================================================
--- trunk/NYTProf.xs (original)
+++ trunk/NYTProf.xs Mon Oct 20 05:17:13 2008
@@ -169,7 +169,7 @@
#define usecputime options[0].option_value
{ "usecputime", 0 },
#define profile_subs options[1].option_value
- { "subs", 1 }, /* sub *inclusive* times
*/
+ { "subs", 1 }, /* subroutine times */
#define profile_blocks options[2].option_value
{ "blocks", 1 }, /* block and sub
*exclusive* times */
#define profile_leave options[3].option_value
@@ -1172,7 +1172,7 @@
found->id, use_db_sub ? "" : ", set use_db_sub=1
option");
}
- if (trace_level) {
+ if (trace_level >= 2) {
/* including last_executed_fid can be handy for tracking down
how
* a file got loaded */
warn("New fid %2u (after %2u:%-4u) %x e%u:%u %.*s %s%s\n",
@@ -1597,7 +1597,7 @@
output_int(last_block_line);
output_int(last_sub_line);
}
- if (trace_level >= 3)
+ if (trace_level >= 4)
warn("Wrote %d:%-4d %2u ticks (%u, %u)\n", last_executed_fid,
last_executed_line, elapsed, last_block_line,
last_sub_line);
}
@@ -1867,9 +1867,9 @@
SV *incl_time_sv = *av_fetch(av, 1, 1);
SV *excl_time_sv = *av_fetch(av, 2, 1);
/* statement overheads we've accumulated since we entered the sub */
- int overhead_ticks = (int)(cumulative_overhead_ticks -
sub_call_start->current_overhead_ticks);
+ NV overhead_ticks = (int)(cumulative_overhead_ticks -
sub_call_start->current_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->current_subr_secs);
NV incl_subr_sec;
NV excl_subr_sec;
@@ -1880,20 +1880,25 @@
else {
time_of_day_t sub_end_time;
unsigned int 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);
- ticks -= overhead_ticks; /* subtract statement
measurement overheads */
- incl_subr_sec = overflow + ticks / (NV)ticks_per_sec;
+
+ incl_subr_sec = overflow + (ticks / (NV)ticks_per_sec);
+ /* subtract statement measurement overheads */
+ incl_subr_sec -= (overhead_ticks / (NV)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)
- warn(" <- %s after %"NVff"s incl - %"NVff"s = %"NVff"s excl
(%"NVff"s @ %s, oh %g-%g=%dt) d%d\n",
+ warn(" <- %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,
- SvNV(incl_time_sv)+incl_subr_sec, sub_call_start->fid_line,
- cumulative_overhead_ticks,
sub_call_start->current_overhead_ticks,
- overhead_ticks, (int)sub_call_start->call_depth);
+ cumulative_subr_secs, sub_call_start->current_subr_secs,
called_sub_secs,
+ cumulative_overhead_ticks,
sub_call_start->current_overhead_ticks, overhead_ticks,
+ (int)sub_call_start->call_depth,
+ sub_call_start->fid_line);
/* only count inclusive time for the outer-most calls */
if (sub_call_start->call_depth <= 1) {
@@ -2295,7 +2300,7 @@
}
#endif
- if (trace_level || profile_zero)
+ if (trace_level)
warn("NYTProf init pid %d, clock %d%s\n", last_pid, profile_clock,
profile_zero ? ", zero=1" : "");
@@ -2696,7 +2701,7 @@
store_attrib_sv(pTHX_ HV *attr_hv, char *text, SV *value_sv)
{
(void)hv_store(attr_hv, text, (I32)strlen(text), value_sv, 0);
- if (trace_level >= 2)
+ if (trace_level >= 1)
warn(": %s = '%s'\n", text, SvPV_nolen(value_sv));
}
@@ -2871,7 +2876,7 @@
unsigned int file_mtime = read_int();
filename_sv = read_str(aTHX_ NULL);
- if (trace_level) {
+ if (trace_level >= 2) {
warn("Fid %2u is %s (eval %u:%u) 0x%x sz%u mt%u\n",
file_num, SvPV_nolen(filename_sv), eval_file_num,
eval_line_num,
fid_flags, file_size, file_mtime);
@@ -3101,7 +3106,7 @@
if (NULL == NYTP_gets(in, text, sizeof(text)))
/* probably EOF */
croak("Profile format error reading comment");
- if (trace_level >= 2)
+ if (trace_level >= 1)
warn("# %s", text); /* includes \n */
break;
}
@@ -3249,7 +3254,7 @@
}
else if (profile_start == NYTP_START_END) {
SV *enable_profile_sv = (SV *)get_cv("DB::enable_profile",
GV_ADDWARN);
- if (trace_level >= 2)
+ if (trace_level >= 1)
warn("enable_profile defered until END");
av_unshift(PL_endav, 1); /* we want to be first */
av_store(PL_endav, 0, SvREFCNT_inc(enable_profile_sv));
Modified: trunk/lib/Devel/NYTProf.pm
==============================================================================
--- trunk/lib/Devel/NYTProf.pm (original)
+++ trunk/lib/Devel/NYTProf.pm Mon Oct 20 05:17:13 2008
@@ -138,9 +138,13 @@
exit is detected via perl's internal save stack. The result is both
extremely
fast and very robust.
-Note that subroutines that recurse directly or indirectly, such as
Error::try,
-will show higher subroutine inclusive times because the time spent recuring
-will be double-counted. That may change in future.
+=head3 Subroutine Recursion
+
+For subroutines that recurse directly or indirectly, such as Error::try,
+the inclusive time is only measured for the outer-most call.
+
+The inclusive times of recursive calls are still measured and are
accumulated
+separately. Also the 'maximum recursion depth' per calling location is
recorded.
=head2 Application Profiling
@@ -232,10 +236,10 @@
=head2 blocks=0
Set to 0 to disable the determination of block and subroutine location per
statement.
-This makes the profiler about 50% faster (as of July 2008) but you loose
some
-valuable information. The extra cost is likely to be reduced in later
versions
-anyway, as little optimization has been done on that part of the code.
-The profiler is fast enough that you shouldn't need to do this.
+This makes the profiler about 50% faster (as of July 2008) and produces
smaller
+output files, but you loose some valuable information. The extra cost is
likely
+to be reduced in later versions anyway, as little optimization has been
done on
+that part of the code.
=head2 leave=0
Added: trunk/t/test70-subexcl.p
==============================================================================
--- (empty file)
+++ trunk/t/test70-subexcl.p Mon Oct 20 05:17:13 2008
@@ -0,0 +1,28 @@
+# This test isn't very useful until we can test subroutine timings
+# perhaps by adding an option to nytprofcsv to include them
+# and adjusting test.pl to test for them (including the ~N fudge factor).
+# Meanwhile the test is useful for sanity checking the subroutine timing
+# code using a command like
+# make && NYTPROF_TEST=trace=3 perl -Mblib test.pl -leave=1 -use_db_sub=0
t/test70-subexcl.*
+
+my $T = 0.2;
+
+sub A { # inclusive ~= $T, exclusive ~= $T
+ select undef, undef, undef, $T;
+}
+
+sub B { # inclusive ~= $T*2, exclusive ~= $T
+ A();
+ select undef, undef, undef, $T;
+}
+
+sub C { # inclusive ~= $T*2, exclusive ~= 0.0
+ B();
+}
+
+sub D { # inclusive ~= $T*4, exclusive ~= 0.0
+ C();
+ C(); # cumulative_subr_secs non-zero on sub entry
+}
+
+D();
--~--~---------~--~----~------------~-------~--~----~
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]
-~----------~----~----~----~------~----~------~--~---
