Revision: 1399
Author: [email protected]
Date: Fri Nov 19 07:23:37 2010
Log: Added special handling for the perl built-in accept()
Effectively the clock stops ticking while in accept().
This makes profiles of pure-perl web servers more useful.
Make profile end time more accurate.
Write out new cumulative_overhead_ticks attribute.
Add new profiler_active attribute as profiler_duration - overhead time.
http://code.google.com/p/perl-devel-nytprof/source/detail?r=1399
Modified:
/trunk/Changes
/trunk/NYTProf.xs
/trunk/bin/nytprofhtml
/trunk/lib/Devel/NYTProf/Data.pm
=======================================
--- /trunk/Changes Tue Nov 9 14:58:56 2010
+++ /trunk/Changes Fri Nov 19 07:23:37 2010
@@ -8,10 +8,19 @@
=head2 Changes in Devel::NYTProf 4.06 (svn XXX) XXX
+TODO: check/update PostgreSQL-PLPerl-NYTProf
+
+ Fixed risk of nytprofhtml failure due to over-long filenames RT#62319
+
Improved handling of Class::MOP/Moose generated methods.
Improved handling of embedded filenames, e.g., "(eval N)[$path]"
Updated and clarified usecputime=1 docs.
Updated tests for new functionality in Sub::Name 0.06.
+ Updated tests for changes in perl 5.13.x.
+
+ Added special handling for the perl built-in accept()
+ Effectively the clock stops ticking while in accept().
+ This makes profiles of pure-perl web servers more useful.
Added --no-mergeevals option to nytprofhtml.
Added "If Statement and Subroutine Timings Don't Match" and
"If Headline Subroutine Timings Don't Match the Called Subs"
=======================================
--- /trunk/NYTProf.xs Sat Oct 30 05:54:27 2010
+++ /trunk/NYTProf.xs Fri Nov 19 07:23:37 2010
@@ -1676,17 +1676,21 @@
static void
close_output_file(pTHX) {
int result;
+ NV timeofday;
if (!out)
return;
+ timeofday = gettimeofday_nv(); /* before write_*() calls */
+ NYTP_write_attribute_nv(out,
STR_WITH_LEN("cumulative_overhead_ticks"), cumulative_overhead_ticks);
+
write_src_of_files(aTHX);
write_sub_line_ranges(aTHX);
write_sub_callers(aTHX);
/* mark end of profile data for last_pid pid
* which is the pid that this file relates to
*/
- NYTP_write_process_end(out, last_pid, gettimeofday_nv());
+ NYTP_write_process_end(out, last_pid, timeofday);
if ((result = NYTP_close(out, 0)))
logwarn("Error closing profile data file: %s\n", strerror(result));
@@ -1785,6 +1789,7 @@
const char *called_subpkg_pv;
SV *called_subnam_sv;
/* ensure all items are initialized in first phase of
pp_subcall_profiler */
+ int hide_subr_call_time; /* eg for CORE:accept */
};
/* save stack index to the current subroutine entry structure */
@@ -1941,6 +1946,17 @@
/* subtract statement measurement overheads */
incl_subr_sec -= (overhead_ticks / CLOCKS_PER_TICK);
}
+
+ if (subr_entry->hide_subr_call_time) {
+ /* account for the time spent in the sub as if it was statement
+ * profiler overhead. That has the effect of neatly subtracting
+ * the time from all the sub calls up the call stack.
+ */
+ cumulative_overhead_ticks += incl_subr_sec * CLOCKS_PER_TICK;
+ incl_subr_sec = 0;
+ called_sub_secs = 0;
+ }
+
/* exclusive = inclusive - time spent in subroutines called by this
subroutine */
excl_subr_sec = incl_subr_sec - called_sub_secs;
@@ -2280,6 +2296,8 @@
}
subr_entry->called_cv_depth = 1; /* an approximation for slowops */
subr_entry->called_is_xs = "sop";
+ if (OP_ACCEPT == op_type)
+ subr_entry->hide_subr_call_time = 1;
}
/* These refer to the last perl statement executed, so aren't
=======================================
--- /trunk/bin/nytprofhtml Tue Nov 9 21:17:52 2010
+++ /trunk/bin/nytprofhtml Fri Nov 19 07:23:37 2010
@@ -310,8 +310,7 @@
</thead>
};
- # XXX may not be appropriate if profiling wasn't continuous
- my $profiler_duration = $profile->{attribute}{profiler_duration};
+ my $profiler_active = $profile->{attribute}{profiler_active};
my @rows;
$sub_links .= "<tbody>\n";
@@ -323,10 +322,10 @@
$sub_links .= determine_severity($sub->caller_count || 0,
$dev_call_count);
$sub_links .= determine_severity($sub->caller_fids || 0,
$dev_call_fids);
$sub_links .= determine_severity($sub->excl_time || 0,
$dev_excl_time, 1,
- sprintf("%.1f%%", $sub->excl_time/$profiler_duration*100)
+ sprintf("%.1f%%", $sub->excl_time/$profiler_active*100)
);
$sub_links .= determine_severity($sub->incl_time || 0,
$dev_incl_time, 1,
- sprintf("%.1f%%", $sub->incl_time/$profiler_duration*100)
+ sprintf("%.1f%%", $sub->incl_time/$profiler_active*100)
);
my @hints;
@@ -734,8 +733,9 @@
# overall description
my @all_fileinfos = $profile->all_fileinfos;
my $eval_fileinfos = $profile->eval_fileinfos;
- my $summary = sprintf "Profile of %s for %s,",
- $application, fmt_time($profile->{attribute}{profiler_duration});
+ my $summary = sprintf "Profile of %s for %s (of %s),", $application,
+ fmt_time($profile->{attribute}{profiler_active}),
+ fmt_time($profile->{attribute}{profiler_duration});
$summary .= sprintf " executing %d statements",
$profile->{attribute}{total_stmts_measured}
-$profile->{attribute}{total_stmts_discounted};
=======================================
--- /trunk/lib/Devel/NYTProf/Data.pm Tue Nov 9 16:55:13 2010
+++ /trunk/lib/Devel/NYTProf/Data.pm Fri Nov 19 07:23:37 2010
@@ -104,6 +104,11 @@
(my $sub_class = $class) =~ s/\w+$/SubInfo/;
$_ and bless $_ => $sub_class for values %$sub_subinfo;
+ # create profiler_active attribute by subtracting from
profiler_duration
+ # currently we only subtract cumulative_overhead_ticks
+ my $attribute = $profile->{attribute};
+ my $overhead_time = $attribute->{cumulative_overhead_ticks} /
$attribute->{ticks_per_sec};
+ $attribute->{profiler_active} = $attribute->{profiler_duration} -
$overhead_time;
# find subs that have calls but no fid
my @homeless_subs = grep { $_->calls and not $_->fid }
values %$sub_subinfo;
@@ -589,7 +594,7 @@
$attributes->{$attr} = 0 if exists $attributes->{$attr};
}
- for my $attr (qw(PL_perldb)) {
+ for my $attr (qw(PL_perldb cumulative_overhead_ticks)) {
delete $attributes->{$attr};
}
--
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]
