Revision: 1189
Author: [email protected]
Date: Mon Apr 19 04:08:57 2010
Log: Delete /tmp/ report dir contents before writing new one from .t --open
Made t/test09.p usefully slower.
Added note to HACKING re using sub profiler to time string evals,
plus adding meta data to csv output to aid testing.
Added cache method to FileInfo to complement meta.
Changed _sum_of_line_time_data to only use line-level times
as a fix for handling evals.
Assorted reporting polish.
http://code.google.com/p/perl-devel-nytprof/source/detail?r=1189
Modified:
/trunk/HACKING
/trunk/bin/nytprofhtml
/trunk/lib/Devel/NYTProf/FileInfo.pm
/trunk/lib/Devel/NYTProf/Reader.pm
/trunk/t/lib/NYTProfTest.pm
/trunk/t/test09.p
/trunk/t/test09.rdt
/trunk/t/test09.x
=======================================
--- /trunk/HACKING Mon Apr 5 16:22:16 2010
+++ /trunk/HACKING Mon Apr 19 04:08:57 2010
@@ -396,3 +396,11 @@
- Add eval information (evals and time) to file summary header
Make generation of call graph .dot files optional and/or optimize to make
faster
+
+String evals could/should be tied into the subroutine profiler.
+That would give inclusive timings which we don't have at the moment.
+The evals appear in the html report as if they're calls but the timings are
+statement timings of the eval fid that don't include time spent in subs
defined
+elsewhere but called from the string eval. The inconsistency is confusing.
+
+Modify csv output to optionally include extra metadata lines. Use for
testing.
=======================================
--- /trunk/bin/nytprofhtml Mon Apr 19 03:06:11 2010
+++ /trunk/bin/nytprofhtml Mon Apr 19 04:08:57 2010
@@ -107,8 +107,8 @@
sub {
my ($profile, $fi, $output_filestr, $level) = @_;
- my $profile_level_buttons =
- get_level_buttons($profile->get_profile_levels,
$output_filestr, $level);
+ my $profile_level_buttons = ($fi->is_eval)
+ ? '' : get_level_buttons($profile->get_profile_levels,
$output_filestr, $level);
my $subhead = qq{  $profile_level_buttons<br />
For ${ \($profile->{attribute}{application}) }
@@ -510,24 +510,30 @@
my $evals_called_html = join "\n", map {
my $eval_fi = $_;
my $sum_of_stmts_time = $eval_fi->sum_of_stmts_time;
+ my $what = "string eval";
my @nested_evals = $eval_fi->has_evals(1);
my ($nest_eval_time, $extra) = (0, '');
if (@nested_evals) {
$nest_eval_time = sum map { $_->sum_of_stmts_time }
@nested_evals;
- $extra = sprintf " (%s in this eval plus %s in %d nested
evals)",
+ $extra .= sprintf " (%s in this eval plus %s in %d nested
evals)",
fmt_time($sum_of_stmts_time),
fmt_time($nest_eval_time),
scalar @nested_evals
if $nest_eval_time;
}
+
+ my $merged_fids = $eval_fi->meta->{merged_fids};
+ if ($merged_fids) {
+ $extra .= sprintf " (data for these has been merged)";
+ $what .= "s";
+ }
my $href = $reporter->href_for_file($eval_fi, undef);
- my $link = ($href)
- ? sprintf(q{<a href="%s">%s</a>}, $href, "string eval")
- : "string eval";
- my $html = sprintf qq{%s# spent %s compiling and
executing %s%s},
+ my $link = ($href) ? sprintf(q{<a href="%s">%s</a>}, $href,
$what) : $what;
+ my $html = sprintf qq{%s# spent %s executing statements
in %s%s%s},
$ws, fmt_time($sum_of_stmts_time+$nest_eval_time, 5),
+ ($merged_fids) ? sprintf("%d ",1+scalar
@$merged_fids) : '',
$link, $extra;
$html;
@@ -648,7 +654,7 @@
}
output_subs_callgraph_dot_file($reporter, "packages-callgraph.dot",
undef, 1);
- print $fh q{<br/>NYTProf also generates call-graph files in }
+ print $fh q{NYTProf also generates call-graph files in }
.q{<a href="http://en.wikipedia.org/wiki/Graphviz";>Graphviz</a>
format: }
.q{<a href="packages-callgraph.dot">inter-package calls</a>};
output_subs_callgraph_dot_file($reporter, "subs-callgraph.dot", undef,
0);
@@ -657,6 +663,10 @@
if $all_subs > 200; # arbitrary
print $fh q{.<br/>};
+ print $fh q{<br/>You can hover over some table cells and headings to
view extra information.};
+ print $fh q{<br/>Some table column headings can be clicked on to sort
the table by that column.};
+ print $fh q{<br/>};
+
output_file_table($fh, $profile, 1);
my $footer = get_footer($profile);
=======================================
--- /trunk/lib/Devel/NYTProf/FileInfo.pm Mon Apr 19 03:06:11 2010
+++ /trunk/lib/Devel/NYTProf/FileInfo.pm Mon Apr 19 04:08:57 2010
@@ -21,8 +21,7 @@
# extra constants for private elements
use constant {
NYTP_FIDi_meta => NYTP_FIDi_elements + 1,
- NYTP_FIDi_sum_stmts_count => NYTP_FIDi_elements + 2,
- NYTP_FIDi_sum_stmts_times => NYTP_FIDi_elements + 3,
+ NYTP_FIDi_cache => NYTP_FIDi_elements + 2,
};
sub filename { shift->[NYTP_FIDi_FILENAME()] }
@@ -46,6 +45,8 @@
# general purpose hash - mainly a hack to help kill off Reader.pm
sub meta { shift->[NYTP_FIDi_meta()] ||= {} }
+# general purpose cache
+sub cache { shift->[NYTP_FIDi_cache()] ||= {} }
# array of fileinfo's for each string eval in the file
sub has_evals {
@@ -195,7 +196,7 @@
return sum(map { $_->sum_of_stmts_count(0) } $self,
$self->has_evals(1))
if $incl_nested_evals;
- my $ref = \$self->[NYTP_FIDi_sum_stmts_count()];
+ my $ref = \$self->cache->{NYTP_FIDi_sum_stmts_count};
$$ref = $self->_sum_of_line_time_data(1)
if not defined $$ref;
@@ -208,7 +209,7 @@
return sum(map { $_->sum_of_stmts_time(0) } $self, $self->has_evals(1))
if $incl_nested_evals;
- my $ref = \$self->[NYTP_FIDi_sum_stmts_times()];
+ my $ref = \$self->cache->{NYTP_FIDi_sum_stmts_times};
$$ref = $self->_sum_of_line_time_data(0)
if not defined $$ref;
@@ -217,7 +218,7 @@
sub _sum_of_line_time_data {
my ($self, $idx) = @_;
- my $line_time_data = $self->line_time_data([qw(sub block line)]);
+ my $line_time_data = $self->line_time_data;
my $sum = 0;
$sum += $_->[$idx]||0 for @$line_time_data;
return $sum;
@@ -253,14 +254,10 @@
} @donors;
my $s_ltd = $survivor->line_time_data; # XXX line only
- my $s_fid = $survivor->line_time_data; # XXX line only
for my $donor_fi (@donors) {
# copy data from donor to survivor then delete donor
- # XXX doesn't update model to edit details for
- # subs defines, subs called, or evals etc.
-
# XXX nested evals not handled yet
warn "collapse_sibling_evals: nested evals not handled"
if $donor_fi->has_evals;
@@ -270,7 +267,7 @@
if $donor_fi->subs_defined;
if (my $sub_call_lines = $donor_fi->sub_call_lines) {
-
+ warn "collapse_sibling_evals: subs called not handled
yet"
}
# copy line time data
=======================================
--- /trunk/lib/Devel/NYTProf/Reader.pm Mon Apr 19 03:06:11 2010
+++ /trunk/lib/Devel/NYTProf/Reader.pm Mon Apr 19 04:08:57 2010
@@ -236,7 +236,7 @@
if (my $evalcalls = $evals_at_line->{$linenum}) {
my $line_stats = $stats_by_line{$linenum} ||= {};
- # %$evals => { fid => $fileinfo } }
+ # %$evals => { fid => $fileinfo }
$line_stats->{'evalcall_info'} = $evalcalls;
$line_stats->{'evalcall_count'} = values %$evalcalls;
@@ -434,9 +434,10 @@
$level ||= $self->current_level;
my $fi = $self->{profile}->fileinfo_of($file);
- #return undef if $fi->is_eval;
return undef if $fi->is_fake;
+ $level = 'line' if $fi->is_eval;
+
my $href = $fi->meta->{$level}->{html_safe};
$href &&= $href.'.html';
$href .= "#$anchor" if defined $anchor;
=======================================
--- /trunk/t/lib/NYTProfTest.pm Sun Apr 18 09:58:54 2010
+++ /trunk/t/lib/NYTProfTest.pm Mon Apr 19 04:08:57 2010
@@ -282,7 +282,9 @@
or die "Profiling $test failed\n";
if ($opts{html}) {
- my $cmd = "$perl $nytprofhtml --file=$profile_datafile
--out=/tmp/$outdir";
+ my $htmloutdir = "/tmp/$outdir";
+ unlink <$htmloutdir/*>;
+ my $cmd = "$perl $nytprofhtml --file=$profile_datafile
--out=$htmloutdir";
$cmd .= " --open" if $opts{open};
run_command($cmd);
}
@@ -369,7 +371,7 @@
SKIP: {
skip 'Expected profile data does not have VMS paths', 1
if $^O eq 'VMS' and $test =~ m/test60|test14/i;
- $profile->normalize_variables;
+ $profile->normalize_variables;
dump_profile_to_file($profile, $test.'_new', $test.'_newp');
my @got = slurp_file($test.'_new'); chomp @got;
my @expected = slurp_file($test); chomp @expected;
@@ -587,4 +589,4 @@
1;
-# vim:ts=8:sw=4
+# vim:ts=8:sw=4:et
=======================================
--- /trunk/t/test09.p Mon Apr 19 03:06:11 2010
+++ /trunk/t/test09.p Mon Apr 19 04:08:57 2010
@@ -5,7 +5,7 @@
}
sub bar {
- eval "1 while (1..10_000)";
+ eval 'for ($a=0; $a < 10_000; ++$a) { ++$b }';
}
foo();
=======================================
--- /trunk/t/test09.rdt Mon Apr 19 03:06:11 2010
+++ /trunk/t/test09.rdt Mon Apr 19 04:08:57 2010
@@ -21,7 +21,7 @@
fid_block_time 2 1 [ 0 1 ]
fid_block_time 2 2 [ 0 1 ]
fid_block_time 2 3 [ 0 1 ]
-fid_block_time 3 1 [ 0 1 ]
+fid_block_time 3 1 [ 0 10002 ]
fid_block_time 4 1 [ 0 1 ]
fid_block_time 4 2 [ 0 1 ]
fid_block_time 4 3 [ 0 1 ]
@@ -48,7 +48,7 @@
fid_line_time 2 1 [ 0 1 ]
fid_line_time 2 2 [ 0 1 ]
fid_line_time 2 3 [ 0 1 ]
-fid_line_time 3 1 [ 0 3 ]
+fid_line_time 3 1 [ 0 30006 ]
fid_line_time 4 1 [ 0 1 ]
fid_line_time 4 2 [ 0 1 ]
fid_line_time 4 3 [ 0 1 ]
@@ -60,7 +60,7 @@
fid_sub_time 2 1 [ 0 1 ]
fid_sub_time 2 2 [ 0 1 ]
fid_sub_time 2 3 [ 0 1 ]
-fid_sub_time 3 1 [ 0 1 ]
+fid_sub_time 3 1 [ 0 10002 ]
fid_sub_time 4 1 [ 0 1 ]
fid_sub_time 4 2 [ 0 1 ]
fid_sub_time 4 3 [ 0 1 ]
=======================================
--- /trunk/t/test09.x Mon Apr 19 03:06:11 2010
+++ /trunk/t/test09.x Mon Apr 19 04:08:57 2010
@@ -8,7 +8,7 @@
0,0,0,}
0,0,0,
0,0,0,sub bar {
-0,3,0,eval "1 while (1..10_000)";
+0,3,0,eval 'for ($a=0; $a < 10_000; ++$a) { ++$b }';
0,0,0,}
0,0,0,
0,1,0,foo();
--
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]
