Revision: 1269
Author: [email protected]
Date: Sat Jun 5 15:40:22 2010
Log: This now, finally, seems to do-the-right-thing for e.g. anon-subs that
get merged
when the string evals that create them get merged.
NYTProf data model hacking is beyond painful!
On the plus side, a profile of perlcritic is now usable because the
thousands
of string evals defining anon subs in PPI::Node::_wanted, now get collapsed
into
just a few different evals that have distinct source code (4196->4 in my
case),
and the thousands of anon subs also get collapsed (to 4 in my case).
http://code.google.com/p/perl-devel-nytprof/source/detail?r=1269
Modified:
/trunk/bin/nytprofhtml
/trunk/lib/Devel/NYTProf/Data.pm
/trunk/lib/Devel/NYTProf/FileInfo.pm
/trunk/lib/Devel/NYTProf/SubInfo.pm
/trunk/t/test13.rdt
/trunk/t/test22-strevala.rdt
/trunk/t/test24-strevalc.rdt
/trunk/t/test50-disable.rdt
/trunk/t/test51-enable.rdt
/trunk/t/test61-submerge.rdt
/trunk/t/test62-subcaller1.rdt
=======================================
--- /trunk/bin/nytprofhtml Sun May 30 01:30:17 2010
+++ /trunk/bin/nytprofhtml Sat Jun 5 15:40:22 2010
@@ -446,14 +446,14 @@
push @callers, [$fid, $_, @{$fid_line_info->{$_}}] for
keys %$fid_line_info;
}
my $total_calls = sum(my @caller_calls = map { $_->[2] } @callers);
- my $max_calls = max(@caller_calls);
- my $avg_per_call = fmt_time($sub_info->incl_time / $total_calls);
-
- push @prologue, sprintf "# spent %s within %s which was called%s",
+
+ push @prologue, sprintf "# spent %s within %s which was called%s:",
fmt_incl_excl_time($sub_info->incl_time, $sub_info->excl_time),
- $sub_info->subname, ($total_calls <= 1)
- ? ""
- : " $total_calls times, avg ${avg_per_call}/call:";
+ $sub_info->subname,
+ ($total_calls <= 1) ? ""
+ : sprintf(" %d times, avg %s/call",
+ $total_calls, fmt_time($sub_info->incl_time /
$total_calls));
+ my $max_calls = max(@caller_calls);
# order by most frequent caller first, then by time
@callers = sort { $b->[2] <=> $a->[2] || $b->[3] <=> $a->[3] }
@callers;
@@ -461,16 +461,23 @@
for my $caller (@callers) {
my ($fid, $line, $count, $incl_time, $excl_time, undef, undef,
undef, undef, $calling_subs) = @$caller;
- my $caller_fi = $profile->fileinfo_of($fid);
-
- my @subnames = sort keys %$calling_subs;
+
+ my @subnames = sort keys %{$calling_subs || {}};
ref $_ and $_ = sprintf "%s (merge of %d subs)", $_->[0],
scalar @$_
for @subnames;
my $subname = (@subnames) ? " by " . join(" or ",
@subnames) : "";
- my $avg_time =
- ($count <= 1)
- ? ""
- : sprintf ", avg %s/call", fmt_time($incl_time / $count);
+
+ my $caller_fi = $profile->fileinfo_of($fid);
+ if (!$caller_fi) { # should never happen
+ warn sprintf "Caller of %s, from fid %d line %d has no
fileinfo (%s)",
+ $sub_info, $fid, $line, $subname;
+ die 2;
+ next;
+ }
+
+ my $avg_time = "";
+ $avg_time = sprintf ", avg %s/call", fmt_time($incl_time /
$count)
+ if $count > 1;
my $times = sprintf " (%s+%s)", fmt_time($excl_time),
fmt_time($incl_time - $excl_time);
=======================================
--- /trunk/lib/Devel/NYTProf/Data.pm Tue Jun 1 13:59:18 2010
+++ /trunk/lib/Devel/NYTProf/Data.pm Sat Jun 5 15:40:22 2010
@@ -43,7 +43,7 @@
use warnings;
use strict;
-use Carp;
+use Carp qw(carp croak cluck);
use Cwd qw(getcwd);
use Scalar::Util qw(blessed);
@@ -101,13 +101,13 @@
$_ and bless $_ => $sub_class for values %$sub_subinfo;
- # find called subs that have no file for
+ # find subs that have calls but no fid
my @homeless_subs = grep { $_->calls and not $_->fid }
values %$sub_subinfo;
if (@homeless_subs) { # give them a home...
# currently just the first existing fileinfo
# XXX ought to create a new dummy fileinfo for them
my $new_fi = $profile->fileinfo_of(1);
- $_->alter_fileinfo(undef, $new_fi) for @homeless_subs;
+ $_->_alter_fileinfo(undef, $new_fi) for @homeless_subs;
}
@@ -200,6 +200,18 @@
return { %{ shift->{sub_subinfo} } }; # shallow copy
}
+sub _disconnect_subinfo {
+ my ($self, $si) = @_;
+ my $subname = $si->subname;
+ my $si2 = delete $self->{sub_subinfo}{$subname};
+ # sanity check
+ carp sprintf "disconnect_subinfo: deleted entry %s %s doesn't match
argument %s %s",
+ ($si2) ? ($si2, $si2->subname) : ('undef', 'undef'),
+ $si, $subname
+ if $si2 != $si or $si2->subname ne $subname;
+ # do more?
+}
+
# package_tree_subinfo_map is like package_subinfo_map but returns
# nested data instead of flattened.
@@ -331,12 +343,12 @@
my ($self, $subname) = @_;
if (not defined $subname) {
- carp "Can't resolve subinfo of undef value";
+ cluck "Can't resolve subinfo of undef value";
return undef;
}
my $si = $self->{sub_subinfo}{$subname}
- or warn carp "Can't resolve subinfo of '$subname'";
+ or cluck "Can't resolve subinfo of '$subname'";
return $si;
}
=======================================
--- /trunk/lib/Devel/NYTProf/FileInfo.pm Tue Jun 1 13:59:18 2010
+++ /trunk/lib/Devel/NYTProf/FileInfo.pm Sat Jun 5 15:40:22 2010
@@ -2,6 +2,7 @@
use strict;
+use Carp;
use List::Util qw(sum max);
use Devel::NYTProf::Util qw(strip_prefix_from_paths);
@@ -74,21 +75,6 @@
}
-sub _delete_eval {
- my ($self, $eval_fi) = @_;
-
- my $eval_fis = $self->[NYTP_FIDi_HAS_EVALS()]
- or return;
- my $count = @$eval_fis;
- @$eval_fis = grep { $_ != $eval_fi } @$eval_fis;
- warn "_delete_eval missed" if @$eval_fis == $count;
-
- # XXX needs to update NYTP_FIDi_SUBS_DEFINED NYTP_FIDi_SUBS_CALLED
- # by moving relevant data up to the parent
-
- return;
-}
-
# return subs defined as list of SubInfo objects
sub subs_defined {
@@ -106,23 +92,23 @@
}
sub _remove_sub_defined {
- my ($self, $subinfo) = @_;
- delete $self->[NYTP_FIDi_SUBS_DEFINED()]->{$subinfo->subname};
+ my ($self, $si) = @_;
+ my $subname = $si->subname;
+ delete $self->[NYTP_FIDi_SUBS_DEFINED()]->{$subname}
+ or carp sprintf "_remove_sub_defined: sub %s wasn't defined
in %d %s",
+ $subname, $self->fid, $self->filename;
}
sub _add_new_sub_defined {
my ($self, $subinfo) = @_;
- my $subs_defined = $self->[NYTP_FIDi_SUBS_DEFINED()];
- if (my $existing_si = $subs_defined->{$subinfo->subname}) {
- warn sprintf "Merging %s sub into existing sub with same name
in %s\n",
- $subinfo->subname, $self->filename;
- $existing_si->merge_in($subinfo);
- @$subinfo = (); # zap!
- }
- else {
- $subs_defined->{$subinfo->subname} = $subinfo;
- }
-
+ my $subname = $subinfo->subname;
+ my $subs_defined = $self->[NYTP_FIDi_SUBS_DEFINED()] ||= {};
+ my $existing_si = $subs_defined->{$subname};
+ croak sprintf "sub %s already defined in fid %d %s",
+ $subname, $self->fid, $self->filename
+ if $existing_si;
+
+ $subs_defined->{$subname} = $subinfo;
}
@@ -149,8 +135,8 @@
{
42 => {
- 'pkg1::foo' => [ 1, 0.02093 ],
- 'pkg1::bar' => [ 1, 0.00154 ],
+ 'pkg1::foo' => [ 1, 0.02093 ],
+ 'pkg1::bar' => [ 1, 0.00154 ],
},
}
@@ -271,19 +257,22 @@
sub collapse_sibling_evals {
- my ($self, $survivor, @donors) = @_;
+ my ($self, $survivor_fi, @donors) = @_;
my $profile = $self->profile;
die "Can't collapse_sibling_evals of non-sibling evals"
- if grep { $_->eval_fid != $survivor->eval_fid or
- $_->eval_line != $survivor->eval_line
+ if grep { $_->eval_fid != $survivor_fi->eval_fid or
+ $_->eval_line != $survivor_fi->eval_line
} @donors;
- my $s_ltd = $survivor->line_time_data; # XXX line only
- my $s_scl = $survivor->sub_call_lines;
+ my $s_ltd = $survivor_fi->line_time_data; # XXX line only
+ my $s_scl = $survivor_fi->sub_call_lines;
for my $donor_fi (@donors) {
- # copy data from donor to survivor then delete donor
+ # copy data from donor to survivor_fi then delete donor
+ warn sprintf "collapse_sibling_evals: processing donor
fid %d: %s\n",
+ $donor_fi->fid, $donor_fi->filename
+ if $trace;
# XXX nested evals not handled yet
warn sprintf "collapse_sibling_evals: nested evals in %s not
handled",
@@ -291,49 +280,37 @@
if $donor_fi->has_evals;
if (my @subs_defined = $donor_fi->subs_defined) {
- warn "collapse_sibling_evals: subs defined not fully handled"
- if $trace;
for my $si (@subs_defined) {
- warn sprintf "Moving fid %d sub %s\n",
- $donor_fi->fid, $si->subname
+ warn sprintf " - moving from fid %d: sub %s\n",
+ $donor_fi->fid, $si->subname
if $trace;
- $donor_fi->_remove_sub_defined($si);
- $survivor->_add_new_sub_defined($si);
- $si->_move_to_fileinfo($survivor);
+ $si->_alter_fileinfo($donor_fi, $survivor_fi);
+ warn sprintf " - moving done\n"
+ if $trace;
}
}
- # '1' => { 'main::foo' => [ 1, '1.38e-05', '1.24e-05', ...,
{ 'main::RUNTIME' => undef } ] }
+ # 1 => { 'main::foo' => [ 1, '1.38e-05', '1.24e-05', ...,
{ 'main::RUNTIME' => undef } ] }
if (my $sub_call_lines = $donor_fi->sub_call_lines) {
- my %subnames_called;
+ my %subnames_called_by_donor;
# merge details of subs called from $donor_fi
while ( my ($line, $sc_hash) = each %$sub_call_lines ) {
my $s_sc_hash = $s_scl->{$line} ||= {};
- while ( my ($subname, $sc_info) = each %$sc_hash ) {
+ for my $subname (keys %$sc_hash ) {
my $s_sc_info = $s_sc_hash->{$subname} ||= [];
- $subnames_called{$subname}++;
-
- if (@$s_sc_info) { # need to merge
- $s_sc_info->[$_] += $sc_info->[$_]
- for 0..5; # XXX
- $s_sc_info->[$_] = max($s_sc_info->[$_],
$sc_info->[$_])
- for (NYTP_SCi_REC_DEPTH);
- $s_sc_info->[NYTP_SCi_CALLING_SUB]->{$_} = undef
- for keys %{ $sc_info->[NYTP_SCi_CALLING_SUB] };
- }
- else {
- @$s_sc_info = @$sc_info;
- }
+
+
Devel::NYTProf::SubInfo::_merge_in_caller_info($s_sc_info, delete
$sc_hash->{$subname}, "eval"); # XXX
+ $subnames_called_by_donor{$subname}++;
}
}
%$sub_call_lines = (); # zap
# update subinfo
- $profile->subinfo_of($_)->alter_fileinfo($donor_fi, $survivor)
- for keys %subnames_called;
+ $profile->subinfo_of($_)->_alter_called_by_fileinfo($donor_fi,
$survivor_fi)
+ for keys %subnames_called_by_donor;
}
@@ -344,17 +321,77 @@
my $s_tld_l = $s_ltd->[$line] ||= [];
$s_tld_l->[$_] += $d_tld_l->[$_] for (0...@$d_tld_l-1);
warn sprintf "%d:%d: @$s_tld_l from @$d_tld_l fid:%d\n",
- $survivor->fid, $line, $donor_fi->fid if 0;
+ $survivor_fi->fid, $line, $donor_fi->fid if 0;
}
- push @{ $survivor->meta->{merged_fids} }, $donor_fi->fid;
- ++$survivor->meta->{merged_fids_src_varied}
- if $donor_fi->src_digest ne $survivor->src_digest;
-
- $self->_delete_eval($donor_fi);
+ push @{ $survivor_fi->meta->{merged_fids} }, $donor_fi->fid;
+ ++$survivor_fi->meta->{merged_fids_src_varied}
+ if $donor_fi->src_digest ne $survivor_fi->src_digest;
+
+ # remove eval from NYTP_FIDi_HAS_EVALS
+ if (my $eval_fis = $self->[NYTP_FIDi_HAS_EVALS()]) {
+ my $count = @$eval_fis;
+ @$eval_fis = grep { $_ != $donor_fi } @$eval_fis;
+ warn "_delete_eval missed" if @$eval_fis == $count;
+ # XXX needs to update NYTP_FIDi_SUBS_DEFINED
NYTP_FIDi_SUBS_CALLED ?
+ }
+
$donor_fi->_nullify;
}
- return $survivor;
+
+ # look for any anon subs that are effectively duplicates
+ # (ie have the same name except for eval seqn)
+ # if more than one for any given name we merge them
+ if (my @subs_defined = $survivor_fi->subs_defined_sorted) {
+ # bucket by normalized name
+ my %newname;
+ for my $si (@subs_defined) {
+ next unless $si->is_anon;
+ (my $newname = $si->subname) =~ s/ \( ((?:re_)?) eval \s \d+
\) /(${1}eval 0)/xg;
+ push @{ $newname{$newname} }, $si;
+ }
+
+ while ( my ($newname, $to_merge) = each %newname ) {
+ my $survivor_si = shift @$to_merge;
+ next unless @$to_merge; # nothing to do
+
+ my $survivor_subname = $survivor_si->subname;
+ warn sprintf "collapse_sibling_evals: merging %d subs
into %s: %s\n",
+ scalar @$to_merge, $survivor_subname,
+ join ", ", map { $_->subname } @$to_merge
+ if $trace;
+
+ for my $delete_si (@$to_merge) {
+ my $delete_subname = $delete_si->subname;
+
+ # for every file that called this sub, find the lines that
made the calls
+ # and change the name to the new sub
+ for my $caller_fid ($delete_si->caller_fids) {
+ my $caller_fi = $profile->fileinfo_of($caller_fid);
+ # sub_call_lines ==> { line => { sub => ... } }
+ for my $subs_called_on_line (values %{
$caller_fi->sub_call_lines }) {
+ my $sc_info = delete
$subs_called_on_line->{$delete_subname}
+ or next;
+ if (my $s_sc_info =
$subs_called_on_line->{$survivor_subname}) {
+
Devel::NYTProf::SubInfo::_merge_in_caller_info($s_sc_info, $sc_info); # XXX
+ }
+ else {
+ $subs_called_on_line->{$survivor_subname} =
$sc_info;
+ }
+ }
+ }
+
+ $survivor_si->merge_in($delete_si);
+ $survivor_fi->_remove_sub_defined($delete_si);
+ $profile->_disconnect_subinfo($delete_si);
+ }
+ }
+ }
+
+ warn sprintf "collapse_sibling_evals done\n"
+ if $trace;
+
+ return $survivor_fi;
}
@@ -487,10 +524,12 @@
if (not $opts->{skip_internal_details}) {
for my $si ($self->subs_defined_sorted) {
+ my ($fl, $ll) = ($si->first_line, $si->last_line);
+ defined $_ or $_ = 'undef' for ($fl, $ll);
printf $fh "%s%s%s%s%s%s-%s\n",
$prefix, 'sub', $separator,
$si->subname(' and '), $separator,
- $si->first_line, $si->last_line;
+ $fl, $ll;
}
# { line => { subname => [...] }, ... }
=======================================
--- /trunk/lib/Devel/NYTProf/SubInfo.pm Tue Jun 1 13:59:18 2010
+++ /trunk/lib/Devel/NYTProf/SubInfo.pm Sat Jun 5 15:40:22 2010
@@ -12,11 +12,21 @@
NYTP_SIi_CALL_COUNT NYTP_SIi_INCL_RTIME NYTP_SIi_EXCL_RTIME
NYTP_SIi_SUB_NAME NYTP_SIi_PROFILE
NYTP_SIi_REC_DEPTH NYTP_SIi_RECI_RTIME NYTP_SIi_CALLED_BY
-
+ NYTP_SIi_elements
+
+ NYTP_SCi_CALL_COUNT
NYTP_SCi_INCL_RTIME NYTP_SCi_EXCL_RTIME NYTP_SCi_RECI_RTIME
- NYTP_SCi_CALLING_SUB
+ NYTP_SCi_REC_DEPTH NYTP_SCi_CALLING_SUB
+ NYTP_SCi_elements
);
+# extra constants for private elements
+use constant {
+ NYTP_SIi_meta => NYTP_SIi_elements + 1,
+ NYTP_SIi_cache => NYTP_SIi_elements + 2,
+};
+
+
my $trace = (($ENV{NYTPROF}||'') =~ m/\b trace=(\d+) /x) && $1; # XXX a
hack
sub fid { shift->[NYTP_SIi_FID] || 0 }
@@ -54,6 +64,13 @@
sub recur_max_depth { shift->[NYTP_SIi_REC_DEPTH] }
sub recur_incl_time { shift->[NYTP_SIi_RECI_RTIME] }
+
+
+# general purpose hash - mainly a hack to help kill off Reader.pm
+sub meta { shift->[NYTP_SIi_meta()] ||= {} }
+# general purpose cache
+sub cache { shift->[NYTP_SIi_cache()] ||= {} }
+
# { fid => { line => [ count, incl_time ] } }
sub caller_fid_line_places {
@@ -95,6 +112,10 @@
return 1 if $self->subname =~ m/(?:^CORE::|::CORE:)\w+$/;
return 0;
}
+
+sub is_anon {
+ shift->subname =~ m/::__ANON__\b/;
+}
sub kind {
my $self = shift;
@@ -111,11 +132,6 @@
}
$self->profile->fileinfo_of($fid);
}
-
-sub _move_to_fileinfo {
- my ($self, $fi) = @_;
- $self->[NYTP_SIi_FID] = $fi->fid;
-}
sub clone { # shallow
my $self = shift;
@@ -141,14 +157,24 @@
}
-sub alter_fileinfo {
+sub _alter_fileinfo {
my ($self, $remove_fi, $new_fi) = @_;
my $remove_fid = ($remove_fi) ? $remove_fi->fid : 0;
my $new_fid = ( $new_fi) ? $new_fi->fid : 0;
- warn sprintf "Altering fileinfo of %s from %d to %d\n",
- $self->subname, $remove_fid, $new_fid
- if $trace;
+ if ($self->fid == $remove_fid) {
+ $self->[NYTP_SIi_FID] = $new_fid;
+
+ $remove_fi->_remove_sub_defined($self) if $remove_fi;
+ $new_fi->_add_new_sub_defined($self) if $new_fi;
+ }
+}
+
+
+sub _alter_called_by_fileinfo {
+ my ($self, $remove_fi, $new_fi) = @_;
+ my $remove_fid = ($remove_fi) ? $remove_fi->fid : 0;
+ my $new_fid = ( $new_fi) ? $new_fi->fid : 0;
# remove mentions of $remove_fid from called-by details
# { fid => { line => [ count, incl, excl, ... ] } }
@@ -156,11 +182,16 @@
my $cb = delete $called_by->{$remove_fid};
if ($cb && $new_fid) {
+
+ warn sprintf "Altering %s to change calls from fid %d to be
from fid %d\n",
+ $self->subname, $remove_fid, $new_fid
+ if $trace;
+
if (my $new_cb = $called_by->{$new_fid}) {
# need to merge $cb into $new_cb
while ( my ($line, $cb_li) = each %$cb ) {
my $dst_line_info = $new_cb->{$line} ||= [];
- _merge_in_caller_info($dst_line_info, $cb->{$line});
+ _merge_in_caller_info($dst_line_info, delete
$cb->{$line}, $self->subname);
}
}
else {
@@ -169,32 +200,9 @@
}
}
- if ($self->fid == $remove_fid) {
- $self->[NYTP_SIi_FID] = $new_fid;
- }
-
- if ($remove_fi and $remove_fi->_remove_sub_defined($self)) {
- $new_fi->_add_new_sub_defined($self);
- }
}
-sub _rename {
- my ($self, $newname) = @_;
-
- my $oldname = $self->[NYTP_SIi_SUB_NAME];
- return if $newname eq $oldname;
-
- $self->[NYTP_SIi_SUB_NAME] = $newname;
-
- $self->fileinfo->_rename_subinfo($self, $newname);
-
- my $callers = $self->caller_fid_line_places || {};
- for my $sc (map { values %$_ } values %$callers) {
- my $caller_subnames = $sc->[NYTP_SCi_CALLING_SUB];
- }
-
-}
# merge details of another sub into this one
@@ -202,75 +210,97 @@
# it's meant for merging things like anon-subs in evals
# e.g., "PPI::Node::__ANON__[(eval 286)[PPI/Node.pm:642]:4]"
sub merge_in {
- my $self = shift;
- my $new = shift;
+ my ($self, $donor, %opts) = @_;
+ my $self_subname = $self->subname;
+ my $donor_subname = $donor->subname;
+
+ warn sprintf "Merging sub %s into %s (%s)\n",
+ $donor_subname, $self_subname, join(" ", %opts)
+ if $trace;
# see also "case NYTP_TAG_SUB_CALLERS:" in
load_profile_data_from_stream()
-
- if ($new->[NYTP_SIi_SUB_NAME] ne $self->[NYTP_SIi_SUB_NAME]) {
- $self->[NYTP_SIi_SUB_NAME] = [ $self->[NYTP_SIi_SUB_NAME] ]
- if not ref $self->[NYTP_SIi_SUB_NAME];
- push @{$self->[NYTP_SIi_SUB_NAME]}, $new->[NYTP_SIi_SUB_NAME];
- }
-
- $self->[NYTP_SIi_FIRST_LINE] = _min($self->[NYTP_SIi_FIRST_LINE],
$new->[NYTP_SIi_FIRST_LINE]);
- $self->[NYTP_SIi_LAST_LINE] = _max($self->[NYTP_SIi_LAST_LINE],
$new->[NYTP_SIi_LAST_LINE]);
- $self->[NYTP_SIi_CALL_COUNT] += $new->[NYTP_SIi_CALL_COUNT];
- $self->[NYTP_SIi_INCL_RTIME] += $new->[NYTP_SIi_INCL_RTIME];
- $self->[NYTP_SIi_EXCL_RTIME] += $new->[NYTP_SIi_EXCL_RTIME];
- $self->[NYTP_SIi_REC_DEPTH] = max($self->[NYTP_SIi_REC_DEPTH],
$new->[NYTP_SIi_REC_DEPTH]);
+ push @{ $self->meta->{merged_sub_names} }, $donor->subname;
+
+ $self->[NYTP_SIi_FIRST_LINE] = _min($self->[NYTP_SIi_FIRST_LINE],
$donor->[NYTP_SIi_FIRST_LINE]);
+ $self->[NYTP_SIi_LAST_LINE] = _max($self->[NYTP_SIi_LAST_LINE],
$donor->[NYTP_SIi_LAST_LINE]);
+ $self->[NYTP_SIi_CALL_COUNT] += $donor->[NYTP_SIi_CALL_COUNT];
+ $self->[NYTP_SIi_INCL_RTIME] += $donor->[NYTP_SIi_INCL_RTIME];
+ $self->[NYTP_SIi_EXCL_RTIME] += $donor->[NYTP_SIi_EXCL_RTIME];
+ $self->[NYTP_SIi_REC_DEPTH] = max($self->[NYTP_SIi_REC_DEPTH],
$donor->[NYTP_SIi_REC_DEPTH]);
# adding reci_rtime is correct only if one sub doesn't call the other
- $self->[NYTP_SIi_RECI_RTIME] += $new->[NYTP_SIi_RECI_RTIME]; # XXX
+ $self->[NYTP_SIi_RECI_RTIME] += $donor->[NYTP_SIi_RECI_RTIME]; # XXX
# { fid => { line => [ count, incl_time, ... ] } }
- my $dst_called_by = $self->[NYTP_SIi_CALLED_BY] ||= {};
- my $src_called_by = $new ->[NYTP_SIi_CALLED_BY] || {};
-
- my $subname = $self->subname(' and ');
+ my $dst_called_by = $self ->[NYTP_SIi_CALLED_BY] ||= {};
+ my $src_called_by = $donor->[NYTP_SIi_CALLED_BY] || {};
# iterate over src and merge into dst
while (my ($fid, $src_line_hash) = each %$src_called_by) {
+
my $dst_line_hash = $dst_called_by->{$fid};
- if (!$dst_line_hash) {
- $dst_called_by->{$fid} = $src_line_hash;
- warn "renamed sub caller $self->[NYTP_SIi_SUB_NAME] into
$subname\n" if $trace;
- next;
- }
- warn "merged sub caller $self->[NYTP_SIi_SUB_NAME] into
$subname\n" if $trace;
+ #if (!$dst_line_hash) { $dst_called_by->{$fid} = $src_line_hash;
next; }
# merge lines in %$src_line_hash into %$dst_line_hash
- while (my ($line, $src_line_info) = each %$src_line_hash) {
+ for my $line (keys %$src_line_hash) {
my $dst_line_info = $dst_line_hash->{$line} ||= [];
- _merge_in_caller_info($dst_line_info, $src_line_info);
+ _merge_in_caller_info($dst_line_info, delete
$src_line_hash->{$line}, "merge in $donor_subname");
}
}
+
return;
}
sub _merge_in_caller_info {
- my ($dst_line_info, $src_line_info) = @_;
-
+ my ($dst_line_info, $src_line_info, $tag) = @_;
+ $tag = ($tag) ? " $tag" : "";
+
+ if (!...@$src_line_info) {
+ carp sprintf "_merge_in_caller_info%s skipped (empty donor)", $tag
+ if $trace;
+ return;
+ }
if (!...@$dst_line_info) {
- @$dst_line_info = @$src_line_info;
- }
- else {
-
- # merge @$src_line_info into @$dst_line_info
- $dst_line_info->[$_] += $src_line_info->[$_] for (
- NYTP_SCi_INCL_RTIME, NYTP_SCi_EXCL_RTIME,
- );
- # ug, we can't really combine recursive incl_time, but this is
better than undef
- $dst_line_info->[NYTP_SCi_RECI_RTIME] =
max($dst_line_info->[NYTP_SCi_RECI_RTIME],
-
$src_line_info->[NYTP_SCi_RECI_RTIME]);
-
- my $src_cs = $src_line_info->[NYTP_SCi_CALLING_SUB]||={};
- my $dst_cs = $dst_line_info->[NYTP_SCi_CALLING_SUB]||={};
- $dst_cs->{$_} = $src_cs->{$_} for keys %$src_cs;
- }
+ @$dst_line_info = (0) x NYTP_SCi_elements;
+ $dst_line_info->[NYTP_SCi_CALLING_SUB] = undef;
+ }
+
+ if ($trace) {
+ carp sprintf "_merge_in_caller_info%s merging:", $tag;
+ warn sprintf " . %s\n", fmt_sc($src_line_info);
+ warn sprintf " + %s\n", fmt_sc($dst_line_info);
+ }
+
+ # merge @$src_line_info into @$dst_line_info
+ $dst_line_info->[$_] += $src_line_info->[$_] for (
+ NYTP_SCi_CALL_COUNT, NYTP_SCi_INCL_RTIME, NYTP_SCi_EXCL_RTIME,
+ );
+ $dst_line_info->[NYTP_SCi_REC_DEPTH] =
max($dst_line_info->[NYTP_SCi_REC_DEPTH],
+
$src_line_info->[NYTP_SCi_REC_DEPTH]);
+ # ug, we can't really combine recursive incl_time, but this is better
than undef
+ $dst_line_info->[NYTP_SCi_RECI_RTIME] =
max($dst_line_info->[NYTP_SCi_RECI_RTIME],
+
$src_line_info->[NYTP_SCi_RECI_RTIME]);
+
+ my $src_cs = $src_line_info->[NYTP_SCi_CALLING_SUB]|| {};
+ my $dst_cs = $dst_line_info->[NYTP_SCi_CALLING_SUB]||={};
+ $dst_cs->{$_} = $src_cs->{$_} for keys %$src_cs;
+
+ warn sprintf " = %s\n", fmt_sc($dst_line_info)
+ if $trace;
+
+ @$src_line_info = (); # zap!
+
return;
}
+sub fmt_sc {
+ my ($sc) = @_;
+ my $dst_cs = $sc->[NYTP_SCi_CALLING_SUB]||{};
+ my $by = join " & ", sort keys %$dst_cs;
+ sprintf "calls %d%s",
+ $sc->[NYTP_SCi_CALL_COUNT], ($by) ? ", by $by" : "";
+}
+
sub caller_fids {
my ($self, $merge_evals) = @_;
@@ -376,6 +406,13 @@
$fid, $line, $separator,
join(" ", map { defined($_) ? $_ : 'undef' } @sc);
}
+
+ # where a sub has had others merged into it, list them
+ my $merge_subs = $self->meta->{merged_sub_names} || [];
+ for my $ms (sort @$merge_subs) {
+ printf $fh "%s%s%s%s\n",
+ $prefix, 'merge_donor', $separator, $ms;
+ }
}
# vim:ts=8:sw=4:et
=======================================
--- /trunk/t/test13.rdt Tue Jun 1 04:28:28 2010
+++ /trunk/t/test13.rdt Sat Jun 5 15:40:22 2010
@@ -29,6 +29,7 @@
fid_fileinfo 1 sub main::bar 7-9
fid_fileinfo 1 sub main::baz 11-17
fid_fileinfo 1 sub main::foo 3-5
+fid_fileinfo 1 sub main::x undef-undef
fid_fileinfo 1 call 4 main::CORE:print [ 3 0 0 0 0 0 0
main::foo ]
fid_fileinfo 1 call 8 main::CORE:print [ 1 0 0 0 0 0 0
main::bar ]
fid_fileinfo 1 call 12 main::CORE:print [ 1 0 0 0 0 0 0
main::baz ]
=======================================
--- /trunk/t/test22-strevala.rdt Tue Jun 1 13:42:18 2010
+++ /trunk/t/test22-strevala.rdt Sat Jun 5 15:40:22 2010
@@ -21,57 +21,41 @@
fid_block_time 2 2 [ 0 1 ]
fid_block_time 3 1 [ 0 1 ]
fid_block_time 3 2 [ 0 1 ]
-fid_block_time 4 1 [ 0 1 ]
-fid_block_time 4 2 [ 0 1 ]
fid_block_time 5 2 [ 0 2 ]
fid_block_time 6 1 [ 0 1 ]
fid_block_time 6 2 [ 0 1 ]
-fid_block_time 7 1 [ 0 1 ]
-fid_block_time 7 2 [ 0 1 ]
fid_fileinfo 1 [ test22-strevala.p 1 2 0 0 ]
fid_fileinfo 1 sub main::BEGIN 0-0
fid_fileinfo 1 sub main::CORE:print 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
fid_fileinfo 1 call 6 main::__ANON__[(eval 1)[test22-strevala.p:6]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 9 main::__ANON__[(eval 2)[test22-strevala.p:9]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 9 main::__ANON__[(eval 3)[test22-strevala.p:9]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 1 call 9 main::__ANON__[(eval 2)[test22-strevala.p:9]:1] [ 2
0 0 0 0 0 0 main::RUNTIME ]
fid_fileinfo 1 eval 6 [ count 1 nested 0 merged 0 ]
-fid_fileinfo 1 eval 9 [ count 2 nested 0 merged 0 ]
-fid_fileinfo 1 eval 12 [ count 1 nested 2 merged 0 ]
+fid_fileinfo 1 eval 9 [ count 1 nested 0 merged 1 ]
+fid_fileinfo 1 eval 12 [ count 1 nested 1 merged 0 ]
fid_fileinfo 2 [ (eval 1)[test22-strevala.p:6] 1 6 2 2 0 0 ]
fid_fileinfo 2 sub main::__ANON__[(eval 1)[test22-strevala.p:6]:1]
1-1
fid_fileinfo 2 call 1 main::CORE:print [ 1 0 0 0 0 0 0
main::__ANON__[(eval 1)[test22-strevala.p:6]:1] ]
fid_fileinfo 3 [ (eval 2)[test22-strevala.p:9] 1 9 3 2 0 0 ]
fid_fileinfo 3 sub main::__ANON__[(eval 2)[test22-strevala.p:9]:1]
1-1
-fid_fileinfo 3 call 1 main::CORE:print [ 1 0 0 0 0 0 0
main::__ANON__[(eval 2)[test22-strevala.p:9]:1] ]
-fid_fileinfo 4 [ (eval 3)[test22-strevala.p:9] 1 9 4 2 0 0 ]
-fid_fileinfo 4 sub main::__ANON__[(eval 3)[test22-strevala.p:9]:1]
1-1
-fid_fileinfo 4 call 1 main::CORE:print [ 1 0 0 0 0 0 0
main::__ANON__[(eval 3)[test22-strevala.p:9]:1] ]
+fid_fileinfo 3 call 1 main::CORE:print [ 2 0 0 0 0 0 0
main::__ANON__[(eval 2)[test22-strevala.p:9]:1]|main::__ANON__[(eval
3)[test22-strevala.p:9]:1] ]
fid_fileinfo 5 [ (eval 4)[test22-strevala.p:12] 1 12 5 2 0 0 ]
-fid_fileinfo 5 call 2 main::__ANON__[(eval 5)[(eval
4)[test22-strevala.p:12]:2]:1] [ 1 0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 5 call 2 main::__ANON__[(eval 6)[(eval
4)[test22-strevala.p:12]:2]:1] [ 1 0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 5 eval 2 [ count 2 nested 0 merged 0 ]
+fid_fileinfo 5 call 2 main::__ANON__[(eval 5)[(eval
4)[test22-strevala.p:12]:2]:1] [ 2 0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 5 eval 2 [ count 1 nested 0 merged 1 ]
fid_fileinfo 6 [ (eval 5)[(eval 4)[test22-strevala.p:12]:2] 5 2 6 2 0
0 ]
fid_fileinfo 6 sub main::__ANON__[(eval 5)[(eval
4)[test22-strevala.p:12]:2]:1] 1-1
-fid_fileinfo 6 call 1 main::CORE:print [ 1 0 0 0 0 0 0
main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1] ]
-fid_fileinfo 7 [ (eval 6)[(eval 4)[test22-strevala.p:12]:2] 5 2 7 2 0
0 ]
-fid_fileinfo 7 sub main::__ANON__[(eval 6)[(eval
4)[test22-strevala.p:12]:2]:1] 1-1
-fid_fileinfo 7 call 1 main::CORE:print [ 1 0 0 0 0 0 0
main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1] ]
+fid_fileinfo 6 call 1 main::CORE:print [ 2 0 0 0 0 0 0
main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1]|
main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1] ]
fid_line_time 1 3 [ 0 1 ]
fid_line_time 1 6 [ 0 1 ]
fid_line_time 1 9 [ 0 2 ]
fid_line_time 1 12 [ 0 1 ]
fid_line_time 2 1 [ 0 1 ]
fid_line_time 2 2 [ 0 1 ]
-fid_line_time 3 1 [ 0 1 ]
-fid_line_time 3 2 [ 0 1 ]
-fid_line_time 4 1 [ 0 1 ]
-fid_line_time 4 2 [ 0 1 ]
+fid_line_time 3 1 [ 0 2 ]
+fid_line_time 3 2 [ 0 2 ]
fid_line_time 5 2 [ 0 2 ]
-fid_line_time 6 1 [ 0 1 ]
-fid_line_time 6 2 [ 0 1 ]
-fid_line_time 7 1 [ 0 1 ]
-fid_line_time 7 2 [ 0 1 ]
+fid_line_time 6 1 [ 0 2 ]
+fid_line_time 6 2 [ 0 2 ]
fid_sub_time 1 3 [ 0 1 ]
fid_sub_time 1 6 [ 0 1 ]
fid_sub_time 1 9 [ 0 2 ]
@@ -80,31 +64,23 @@
fid_sub_time 2 2 [ 0 1 ]
fid_sub_time 3 1 [ 0 1 ]
fid_sub_time 3 2 [ 0 1 ]
-fid_sub_time 4 1 [ 0 1 ]
-fid_sub_time 4 2 [ 0 1 ]
fid_sub_time 5 2 [ 0 2 ]
fid_sub_time 6 1 [ 0 1 ]
fid_sub_time 6 2 [ 0 1 ]
-fid_sub_time 7 1 [ 0 1 ]
-fid_sub_time 7 2 [ 0 1 ]
profile_modes fid_block_time block
profile_modes fid_line_time line
profile_modes fid_sub_time sub
sub_subinfo main::BEGIN [ 1:0-0 calls 0 times 0 0 0 0 ]
sub_subinfo main::CORE:print [ 1:0-0 calls 5 times 0 0 0 0 ]
sub_subinfo main::CORE:print called_by 2:1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 1)[test22-strevala.p:6]:1] ]
-sub_subinfo main::CORE:print called_by 3:1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 2)[test22-strevala.p:9]:1] ]
-sub_subinfo main::CORE:print called_by 4:1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 3)[test22-strevala.p:9]:1] ]
-sub_subinfo main::CORE:print called_by 6:1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1] ]
-sub_subinfo main::CORE:print called_by 7:1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1] ]
+sub_subinfo main::CORE:print called_by 3:1 [ 2 0 0 0 0 0 0
main::__ANON__[(eval 2)[test22-strevala.p:9]:1]|main::__ANON__[(eval
3)[test22-strevala.p:9]:1] ]
+sub_subinfo main::CORE:print called_by 6:1 [ 2 0 0 0 0 0 0
main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1]|
main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1] ]
sub_subinfo main::RUNTIME [ 1:1-1 calls 0 times 0 0 0 0 ]
sub_subinfo main::__ANON__[(eval 1)[test22-strevala.p:6]:1] [ 2:1-1 calls
1 times 0 0 0 0 ]
sub_subinfo main::__ANON__[(eval 1)[test22-strevala.p:6]:1] called_by 1:6
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 2)[test22-strevala.p:9]:1] [ 3:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 2)[test22-strevala.p:9]:1] called_by 1:9
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 3)[test22-strevala.p:9]:1] [ 4:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 3)[test22-strevala.p:9]:1] called_by 1:9
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1] [
6:1-1 calls 1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1]
called_by 5:2 [ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1] [
7:1-1 calls 1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1]
called_by 5:2 [ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 2)[test22-strevala.p:9]:1] [ 3:1-1 calls
2 times 0 0 0 0 ]
+sub_subinfo main::__ANON__[(eval 2)[test22-strevala.p:9]:1] called_by 1:9
[ 2 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 2)[test22-strevala.p:9]:1] merge_donor
main::__ANON__[(eval 3)[test22-strevala.p:9]:1]
+sub_subinfo main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1] [
6:1-1 calls 2 times 0 0 0 0 ]
+sub_subinfo main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1]
called_by 5:2 [ 2 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 5)[(eval 4)[test22-strevala.p:12]:2]:1]
merge_donor main::__ANON__[(eval 6)[(eval 4)[test22-strevala.p:12]:2]:1]
=======================================
--- /trunk/t/test24-strevalc.rdt Tue Jun 1 13:42:18 2010
+++ /trunk/t/test24-strevalc.rdt Sat Jun 5 15:40:22 2010
@@ -22,11 +22,10 @@
fid_block_time 6 1 [ 0 1 ]
fid_block_time 7 1 [ 0 1 ]
fid_block_time 8 1 [ 0 2 ]
-fid_block_time 9 1 [ 0 2 ]
fid_fileinfo 1 [ test24-strevalc.p 1 2 0 0 ]
fid_fileinfo 1 sub main::BEGIN 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
-fid_fileinfo 1 eval 8 [ count 5 nested 2 merged 1 ]
+fid_fileinfo 1 eval 8 [ count 4 nested 2 merged 2 ]
fid_fileinfo 2 [ (eval 1)[test24-strevalc.p:8] 1 8 2 2 0 0 ]
fid_fileinfo 4 [ (eval 3)[test24-strevalc.p:8] 1 8 4 2 0 0 ]
fid_fileinfo 4 eval 1 [ count 1 nested 0 merged 0 ]
@@ -36,10 +35,7 @@
fid_fileinfo 7 [ (eval 6)[(eval 5)[test24-strevalc.p:8]:1] 6 1 7 2 0 0
]
fid_fileinfo 8 [ (eval 7)[test24-strevalc.p:8] 1 8 8 2 0 0 ]
fid_fileinfo 8 sub main::__ANON__[(eval 7)[test24-strevalc.p:8]:1]
1-1
-fid_fileinfo 8 call 1 main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 9 [ (eval 8)[test24-strevalc.p:8] 1 8 9 2 0 0 ]
-fid_fileinfo 9 sub main::__ANON__[(eval 8)[test24-strevalc.p:8]:1]
1-1
-fid_fileinfo 9 call 1 main::__ANON__[(eval 8)[test24-strevalc.p:8]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 8 call 1 main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] [ 2
0 0 0 0 0 0 main::RUNTIME ]
fid_line_time 1 2 [ 0 1 ]
fid_line_time 1 7 [ 0 1 ]
fid_line_time 1 8 [ 0 6 ]
@@ -48,8 +44,7 @@
fid_line_time 5 1 [ 0 1 ]
fid_line_time 6 1 [ 0 1 ]
fid_line_time 7 1 [ 0 1 ]
-fid_line_time 8 1 [ 0 2 ]
-fid_line_time 9 1 [ 0 2 ]
+fid_line_time 8 1 [ 0 4 ]
fid_sub_time 1 2 [ 0 1 ]
fid_sub_time 1 7 [ 0 1 ]
fid_sub_time 1 8 [ 0 6 ]
@@ -59,13 +54,11 @@
fid_sub_time 6 1 [ 0 1 ]
fid_sub_time 7 1 [ 0 1 ]
fid_sub_time 8 1 [ 0 2 ]
-fid_sub_time 9 1 [ 0 2 ]
profile_modes fid_block_time block
profile_modes fid_line_time line
profile_modes fid_sub_time sub
sub_subinfo main::BEGIN [ 1:0-0 calls 0 times 0 0 0 0 ]
sub_subinfo main::RUNTIME [ 1:1-1 calls 0 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] [ 8:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] called_by 8:1
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 8)[test24-strevalc.p:8]:1] [ 9:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 8)[test24-strevalc.p:8]:1] called_by 9:1
[ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] [ 8:1-1 calls
2 times 0 0 0 0 ]
+sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] called_by 8:1
[ 2 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:8]:1] merge_donor
main::__ANON__[(eval 8)[test24-strevalc.p:8]:1]
=======================================
--- /trunk/t/test50-disable.rdt Tue Jun 1 04:28:28 2010
+++ /trunk/t/test50-disable.rdt Sat Jun 5 15:40:22 2010
@@ -18,6 +18,7 @@
fid_block_time 1 4 [ 0 1 ]
fid_block_time 1 5 [ 0 1 ]
fid_fileinfo 1 [ test50-disable.p 1 2 0 0 ]
+fid_fileinfo 1 sub DB::disable_profile 0-0
fid_fileinfo 1 sub main::BEGIN 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
fid_fileinfo 1 call 2 DB::disable_profile [ 1 0 0 0 0 0 0
main::RUNTIME ]
=======================================
--- /trunk/t/test51-enable.rdt Tue Jun 1 04:28:28 2010
+++ /trunk/t/test51-enable.rdt Sat Jun 5 15:40:22 2010
@@ -19,6 +19,7 @@
fid_block_time 1 7 [ 0 1 ]
fid_block_time 1 16 [ 0 1 ]
fid_fileinfo 1 [ test51-enable.p 1 2 0 0 ]
+fid_fileinfo 1 sub DB::disable_profile 0-0
fid_fileinfo 1 sub main::BEGIN 0-0
fid_fileinfo 1 sub main::CORE:unlink 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
=======================================
--- /trunk/t/test61-submerge.rdt Tue Jun 1 13:42:18 2010
+++ /trunk/t/test61-submerge.rdt Sat Jun 5 15:40:22 2010
@@ -18,47 +18,27 @@
fid_block_time 1 8 [ 0 2 ]
fid_block_time 2 1 [ 0 1 ]
fid_block_time 2 2 [ 0 1 ]
-fid_block_time 3 1 [ 0 1 ]
-fid_block_time 3 2 [ 0 1 ]
-fid_block_time 4 1 [ 0 1 ]
-fid_block_time 4 2 [ 0 1 ]
fid_fileinfo 1 [ test61-submerge.p 1 2 0 0 ]
fid_fileinfo 1 sub main::BEGIN 0-0
fid_fileinfo 1 sub main::CORE:print 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
fid_fileinfo 1 sub main::foo 4-4
fid_fileinfo 1 call 4 main::CORE:print [ 3 0 0 0 0 0 0
main::foo ]
-fid_fileinfo 1 call 8 main::__ANON__[(eval 1)[test61-submerge.p:8]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 8 main::__ANON__[(eval 2)[test61-submerge.p:8]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 8 main::__ANON__[(eval 3)[test61-submerge.p:8]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 eval 8 [ count 3 nested 0 merged 0 ]
+fid_fileinfo 1 call 8 main::__ANON__[(eval 1)[test61-submerge.p:8]:1] [ 3
0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 1 eval 8 [ count 1 nested 0 merged 2 ]
fid_fileinfo 2 [ (eval 1)[test61-submerge.p:8] 1 8 2 2 0 0 ]
fid_fileinfo 2 sub main::__ANON__[(eval 1)[test61-submerge.p:8]:1]
1-1
-fid_fileinfo 2 call 1 main::foo [ 1 0 0 0 0 0 0 main::__ANON__[(eval
1)[test61-submerge.p:8]:1] ]
-fid_fileinfo 3 [ (eval 2)[test61-submerge.p:8] 1 8 3 2 0 0 ]
-fid_fileinfo 3 sub main::__ANON__[(eval 2)[test61-submerge.p:8]:1]
1-1
-fid_fileinfo 3 call 1 main::foo [ 1 0 0 0 0 0 0 main::__ANON__[(eval
2)[test61-submerge.p:8]:1] ]
-fid_fileinfo 4 [ (eval 3)[test61-submerge.p:8] 1 8 4 2 0 0 ]
-fid_fileinfo 4 sub main::__ANON__[(eval 3)[test61-submerge.p:8]:1]
1-1
-fid_fileinfo 4 call 1 main::foo [ 1 0 0 0 0 0 0 main::__ANON__[(eval
3)[test61-submerge.p:8]:1] ]
+fid_fileinfo 2 call 1 main::foo [ 3 0 0 0 0 0 0 main::__ANON__[(eval
2)[test61-submerge.p:8]:1]|main::__ANON__[(eval 1)[test61-submerge.p:8]:1]|
main::__ANON__[(eval 3)[test61-submerge.p:8]:1] ]
fid_line_time 1 4 [ 0 3 ]
fid_line_time 1 6 [ 0 1 ]
fid_line_time 1 8 [ 0 2 ]
-fid_line_time 2 1 [ 0 1 ]
-fid_line_time 2 2 [ 0 1 ]
-fid_line_time 3 1 [ 0 1 ]
-fid_line_time 3 2 [ 0 1 ]
-fid_line_time 4 1 [ 0 1 ]
-fid_line_time 4 2 [ 0 1 ]
+fid_line_time 2 1 [ 0 3 ]
+fid_line_time 2 2 [ 0 3 ]
fid_sub_time 1 4 [ 0 3 ]
fid_sub_time 1 6 [ 0 1 ]
fid_sub_time 1 8 [ 0 2 ]
fid_sub_time 2 1 [ 0 1 ]
fid_sub_time 2 2 [ 0 1 ]
-fid_sub_time 3 1 [ 0 1 ]
-fid_sub_time 3 2 [ 0 1 ]
-fid_sub_time 4 1 [ 0 1 ]
-fid_sub_time 4 2 [ 0 1 ]
profile_modes fid_block_time block
profile_modes fid_line_time line
profile_modes fid_sub_time sub
@@ -66,13 +46,9 @@
sub_subinfo main::CORE:print [ 1:0-0 calls 3 times 0 0 0 0 ]
sub_subinfo main::CORE:print called_by 1:4 [ 3 0 0 0 0 0 0
main::foo ]
sub_subinfo main::RUNTIME [ 1:1-1 calls 0 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 1)[test61-submerge.p:8]:1] [ 2:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 1)[test61-submerge.p:8]:1] called_by 1:8
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 2)[test61-submerge.p:8]:1] [ 3:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 2)[test61-submerge.p:8]:1] called_by 1:8
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 3)[test61-submerge.p:8]:1] [ 4:1-1 calls
1 times 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 3)[test61-submerge.p:8]:1] called_by 1:8
[ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 1)[test61-submerge.p:8]:1] [ 2:1-1 calls
3 times 0 0 0 0 ]
+sub_subinfo main::__ANON__[(eval 1)[test61-submerge.p:8]:1] called_by 1:8
[ 3 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 1)[test61-submerge.p:8]:1] merge_donor
main::__ANON__[(eval 2)[test61-submerge.p:8]:1]
+sub_subinfo main::__ANON__[(eval 1)[test61-submerge.p:8]:1] merge_donor
main::__ANON__[(eval 3)[test61-submerge.p:8]:1]
sub_subinfo main::foo [ 1:4-4 calls 3 times 0 0 0 0 ]
-sub_subinfo main::foo called_by 2:1 [ 1 0 0 0 0 0 0 main::__ANON__[(eval
1)[test61-submerge.p:8]:1] ]
-sub_subinfo main::foo called_by 3:1 [ 1 0 0 0 0 0 0 main::__ANON__[(eval
2)[test61-submerge.p:8]:1] ]
-sub_subinfo main::foo called_by 4:1 [ 1 0 0 0 0 0 0 main::__ANON__[(eval
3)[test61-submerge.p:8]:1] ]
+sub_subinfo main::foo called_by 2:1 [ 3 0 0 0 0 0 0 main::__ANON__[(eval
2)[test61-submerge.p:8]:1]|main::__ANON__[(eval 1)[test61-submerge.p:8]:1]|
main::__ANON__[(eval 3)[test61-submerge.p:8]:1] ]
=======================================
--- /trunk/t/test62-subcaller1.rdt Tue Jun 1 04:28:28 2010
+++ /trunk/t/test62-subcaller1.rdt Sat Jun 5 15:40:22 2010
@@ -39,6 +39,7 @@
fid_block_time 2 11 [ 0 1 ]
fid_block_time 2 15 [ 0 1 ]
fid_fileinfo 1 [ test62-subcaller1.p 1 2 0 0 ]
+fid_fileinfo 1 sub Devel::NYTProf::Test::example_xsub
undef-undef
fid_fileinfo 1 sub MyTie::FETCH 7-7
fid_fileinfo 1 sub MyTie::STORE 8-8
fid_fileinfo 1 sub MyTie::TIESCALAR 6-6
--
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]
