Revision: 1070
Author: tim.bunce
Date: Sat Feb 20 05:21:47 2010
Log: Implemented usecputime=1 support for subroutine profiler.
Added 'conjectural terminology' re abstract clocks and measures.
http://code.google.com/p/perl-devel-nytprof/source/detail?r=1070
Modified:
/trunk/Changes
/trunk/HACKING
/trunk/NYTProf.xs
/trunk/lib/Devel/NYTProf.pm
/trunk/t/61-cputime.t
=======================================
--- /trunk/Changes Thu Jan 21 04:42:23 2010
+++ /trunk/Changes Sat Feb 20 05:21:47 2010
@@ -15,13 +15,11 @@
=head2 Changes in Devel::NYTProf 3.02
-XXX Fixed one problem with usecputime=1 option but results are *10 on my
mac.
-XXX Needs tests.
-
- Fixed handling of usecputime=1 option but updated
+ Fixed handling of usecputime=1 option and updated
docs to note the significant limitations.
Fixed handling of assignment of XS subs to files
in some edge cases thanks to Nicholas Clark.
+ Fixed nytprofmerge edge-cases thanks to Nicholas Clark.
Added high-resolution (100ns) timer for Mac OS X
many thanks to Markus Peter.
=======================================
--- /trunk/HACKING Tue Jan 5 09:39:16 2010
+++ /trunk/HACKING Sat Feb 20 05:21:47 2010
@@ -145,6 +145,15 @@
User could then pick a clock by name. By default we'd pick the best
available
realtime clock (or best available cputime clock if usecputime=1 option
set).
+[Conjectural terminology: "clock" means some measuring mechanism, like
+get_clock(), times(), getrusage(), that may yield multiple pieces of
+information, and "measure" is one specific item.
+Clock "time"=times(), measures: "time.user", "time.user+sys" etc
+Clock "clock"=clock_gettime(),
measures: "clock.realtime", "clock.monotonic" etc
+Clock "rusage"=getrusage(), measures: "rusage.majflt", "rusage.nvcsw" etc
+Clock "memory" measures: "memory.bytes", "mem.allocs" etc
+]
+
Add help option which would print a summary of the options and exit.
Could also print list of available clocks for the clock=N option
(using a set of #ifdef's)
=======================================
--- /trunk/NYTProf.xs Sat Feb 20 04:45:40 2010
+++ /trunk/NYTProf.xs Sat Feb 20 05:21:47 2010
@@ -2,13 +2,14 @@
* ************************************************************************
* This file is part of the Devel::NYTProf package.
* Copyright 2008 Adam J. Kaplan, The New York Times Company.
- * Copyright 2008 Tim Bunce, Ireland.
+ * Copyright 2009-2010 Tim Bunce, Ireland.
* Released under the same terms as Perl 5.8
* See http://search.cpan.org/dist/Devel-NYTProf/
*
* Contributors:
- * Adam Kaplan, akaplan at nytimes.com
* Tim Bunce, http://www.tim.bunce.name and http://blog.timbunce.org
+ * Nicholas Clark,
+ * Adam Kaplan, akaplan at nytimes.com
* Steve Peters, steve at fisharerojo.org
*
* ************************************************************************
@@ -1713,7 +1714,8 @@
long unsigned subr_call_seqn;
I32 prev_subr_entry_ix; /* ix to callers subr_entry */
- time_of_day_t initial_call_time;
+ time_of_day_t initial_call_timeofday;
+ struct tms initial_call_cputimes;
NV initial_overhead_ticks;
NV initial_subr_secs;
@@ -1857,8 +1859,15 @@
/* seconds spent in subroutines called by this subroutine */
called_sub_secs = (cumulative_subr_secs -
subr_entry->initial_subr_secs);
- if (0 && profile_usecputime) {
- /* XXX */
+ if (profile_usecputime) {
+ struct tms call_end_ctime;
+ long ticks;
+
+ times(&call_end_ctime);
+ ticks = (call_end_ctime.tms_utime -
subr_entry->initial_call_cputimes.tms_utime)
+ + (call_end_ctime.tms_stime -
subr_entry->initial_call_cputimes.tms_stime);
+ /* ignore overhead_ticks when using cputime because the resolution
is so poor */
+ incl_subr_sec = (ticks / (NV)CLK_TCK);
}
else {
time_of_day_t sub_end_time;
@@ -1866,14 +1875,14 @@
/* calculate ticks since we entered the sub */
get_time_of_day(sub_end_time);
- get_ticks_between(subr_entry->initial_call_time, sub_end_time,
ticks, overflow);
+ get_ticks_between(subr_entry->initial_call_timeofday,
sub_end_time, ticks, overflow);
incl_subr_sec = overflow + (ticks / (NV)CLOCKS_PER_TICK);
/* subtract statement measurement overheads */
incl_subr_sec -= (overhead_ticks / CLOCKS_PER_TICK);
- /* exclusive = inclusive - time spent in subroutines called by
this subroutine */
- excl_subr_sec = incl_subr_sec - called_sub_secs;
- }
+ }
+ /* exclusive = inclusive - time spent in subroutines called by this
subroutine */
+ excl_subr_sec = incl_subr_sec - called_sub_secs;
subr_call_key_len = sprintf(subr_call_key, "%s::%s[%u:%d]",
subr_entry->caller_subpkg_pv,
@@ -2147,7 +2156,10 @@
subr_entry->subr_prof_depth = (caller_subr_entry)
? caller_subr_entry->subr_prof_depth+1 : 1;
- get_time_of_day(subr_entry->initial_call_time);
+ if (profile_usecputime)
+ times(&subr_entry->initial_call_cputimes);
+ else
+ get_time_of_day(subr_entry->initial_call_timeofday);
subr_entry->initial_overhead_ticks = cumulative_overhead_ticks;
subr_entry->initial_subr_secs = cumulative_subr_secs;
subr_entry->subr_call_seqn = ++cumulative_subr_seqn;
@@ -2776,7 +2788,7 @@
/* Save the process id early. We monitor it to detect forks */
last_pid = getpid();
- ticks_per_sec = (profile_usecputime) ? CLOCKS_PER_SEC :
CLOCKS_PER_TICK;
+ ticks_per_sec = (profile_usecputime) ? CLK_TCK : CLOCKS_PER_TICK;
DB_INIT_cv = (SV*)GvCV(gv_fetchpv("DB::_INIT", FALSE,
SVt_PVCV));
DB_fin_cv = (SV*)GvCV(gv_fetchpv("DB::finish_profile", FALSE,
SVt_PVCV));
=======================================
--- /trunk/lib/Devel/NYTProf.pm Thu Jan 21 04:42:23 2010
+++ /trunk/lib/Devel/NYTProf.pm Sat Feb 20 05:21:47 2010
@@ -427,7 +427,7 @@
=head2 usecputime=1
Measure user CPU + system CPU time instead of the real elapsed 'wall clock'
-time (which is the default). This currently only applies to the statement
profiler.
+time (which is the default).
Measuring CPU time has the advantage of making the measurements
independent of
time spent blocked waiting for the cpu or network i/o etc. But it also has
the
=======================================
--- /trunk/t/61-cputime.t Sat Feb 20 04:42:34 2010
+++ /trunk/t/61-cputime.t Sat Feb 20 05:21:47 2010
@@ -16,7 +16,7 @@
# restrict irrelevant options:
compress => 1, slowops => 0, savesrc => 0, leave => 0, stmts => 0,
},
- extra_test_count => 5,
+ extra_test_count => 6,
extra_test_code => sub {
my ($profile, $env) = @_;
@@ -39,12 +39,12 @@
last if $crnt >= $end;
}
- warn "cputime loop count $loops\n";
+ print "cputime loop count $loops\n";
}
# sync up: spin till clock ticks
1 while $cpu1 == ($cpu2 = (times)[0]);
- warn "cputime step ".($cpu2-$cpu1)."\n";
+ print "cputime step ".($cpu2-$cpu1)."\n";
# record start time
my $start = time();
@@ -53,7 +53,7 @@
foo($cpu2 + 0.4);
# report realtime to help identify is cputime is really
measuring realtime
- warn "realtime used ".(time()-$start)."\n";
+ print "realtime used ".(time()-$start)."\n";
};
$profile = profile_this(
--
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]
