Revision: 1210
Author: [email protected]
Date: Mon May 3 13:49:06 2010
Log: No longer normalise eval sequence numbers to 0 on loading a profile.
Normalise to 0 when dumping data for (most) tests.
Tweak wording of negative time warnings.
Use perl -f in NYTProfTest to skip sitecustomize.pl.
Updated and reorganized Changes file entry.
http://code.google.com/p/perl-devel-nytprof/source/detail?r=1210
Modified:
/trunk/Changes
/trunk/NYTProf.xs
/trunk/lib/Devel/NYTProf/Data.pm
/trunk/lib/Devel/NYTProf/FileInfo.pm
/trunk/lib/Devel/NYTProf/SubInfo.pm
/trunk/t/40-savesrc.t
/trunk/t/lib/NYTProfTest.pm
/trunk/t/test22-strevala.rdt
/trunk/t/test22-strevala.t
/trunk/t/test24-strevalc.rdt
/trunk/t/test24-strevalc.t
/trunk/t/test61-submerge.rdt
/trunk/t/test61-submerge.t
=======================================
--- /trunk/Changes Thu Apr 22 07:34:15 2010
+++ /trunk/Changes Mon May 3 13:49:06 2010
@@ -19,23 +19,34 @@
Refine and document handing of string evals
Consider eval_pv from outside perl, e.g. plperl
- Fixed off-by-1 error in number of Files an xsub/opcode was called from.
+Major changes:
+
+ Added profile reporting of code executed in string evals.
+ Each string eval executed gets it's own report page.
+ String evals may be collapsed/merged in some cases.
Enabled savesrc=1 by default.
- Added profile reporting of code executed in string evals.
- Each string eval gets its own report page. String evals that don't
define
- subs or use string eval themselves may be collapsed/merged in some
cases.
+Other changes:
+
+ Fixed off-by-1 error in number of Files an xsub/opcode was called from.
+ Fixed Devel::NYTProf::Apache to work in more situations.
+
+ Improved behaviour for 'duplicate' anon-subs defined in separate
+ invocations of a particular string eval.
Added automatic detection of calls to POSIX::_exit() by the sub profiler
so finish_profile() gets called and a usable profile is produced.
Added posix_exit=1 option to do the same thing (in a different way)
- when the sub profiler is not beeing used (i.e., subs=0).
-
- Corrected typos in nytprofhtml docs thanks to [email protected]
+ when the sub profiler is not being used (i.e., subs=0).
+
+Documentation Changes:
Sequences of blank lines are skipped in generated reports.
Relevant for savesrc mode in which perl doesn't store pod sections.
+ Corrected typos in nytprofhtml docs thanks to [email protected].
+ Documented how to use Devel::NYTProf::Apache with virtual hosts that
+ use the PerlOptions +Parent or +Clone configuration.
=head2 Changes in Devel::NYTProf 3.11 (svn 1171) 12th March 2010
=======================================
--- /trunk/NYTProf.xs Wed Apr 28 10:05:03 2010
+++ /trunk/NYTProf.xs Mon May 3 13:49:06 2010
@@ -3217,8 +3217,8 @@
if (sc[NYTP_SCi_INCL_RTIME] < 0.0 || sc[NYTP_SCi_EXCL_RTIME] <
0.0) {
++negative_time_calls;
if (trace_level) {
- logwarn("%s call has negative time: incl %"NVff"s,
excl %"NVff"s (clock id %d)\n",
- called_subname, sc[NYTP_SCi_INCL_RTIME],
sc[NYTP_SCi_EXCL_RTIME], profile_clock);
+ logwarn("%s call has negative time: incl %"NVff"s,
excl %"NVff"s:\n",
+ called_subname, sc[NYTP_SCi_INCL_RTIME],
sc[NYTP_SCi_EXCL_RTIME]);
trace = 1;
}
}
@@ -3237,7 +3237,7 @@
}
}
if (negative_time_calls) {
- logwarn("Warning: %d subroutine calls had negative time! The clock
being used (%d) and the results you'll get are likely to be unstable.\n",
+ logwarn("Warning: %d subroutine calls had negative time! The clock
being used (%d) is probably unstable, so the results will be as well.\n",
negative_time_calls, profile_clock);
}
}
@@ -3383,6 +3383,8 @@
char *start = SvPV(sv, len);
char *first_space;
+ return; /* XXX normalize_eval_seqn is currently disabled */
+
/* effectively does
s/(
\( # first character is literal (
=======================================
--- /trunk/lib/Devel/NYTProf/Data.pm Fri Apr 30 14:42:54 2010
+++ /trunk/lib/Devel/NYTProf/Data.pm Mon May 3 13:49:06 2010
@@ -565,8 +565,18 @@
}
}
- # zero sub info and sub caller times
- $_->normalize_for_test for values %{ $self->{sub_subinfo} };
+ my $sub_subinfo = $self->{sub_subinfo};
+ for my $subname (keys %$sub_subinfo) {
+ my $si = $self->{sub_subinfo}{$subname};
+ # zero sub info and sub caller times etc.
+ my $newname = $si->normalize_for_test;
+ if ($newname ne $subname) {
+ warn "Normalizing $subname to $newname overwrote other data\n"
+ if $sub_subinfo->{$newname};
+ $sub_subinfo->{$newname} = delete $sub_subinfo->{$subname};
+ }
+ }
+
$_->normalize_for_test for $self->all_fileinfos;
return;
=======================================
--- /trunk/lib/Devel/NYTProf/FileInfo.pm Wed Apr 28 10:00:26 2010
+++ /trunk/lib/Devel/NYTProf/FileInfo.pm Mon May 3 13:49:06 2010
@@ -413,12 +413,27 @@
# normalize flags to avoid failures due to savesrc and perl version
$self->[NYTP_FIDi_FLAGS] &= ~(NYTP_FIDf_HAS_SRC|NYTP_FIDf_SAVE_SRC);
- for my $sc (map { values %$_ } values %{ $self->sub_call_lines }) {
- $sc->[NYTP_SCi_INCL_RTIME] =
- $sc->[NYTP_SCi_EXCL_RTIME] =
- $sc->[NYTP_SCi_RECI_RTIME] = 0;
- }
-
+ # '1' => { 'main::foo' => [ 1, '1.38e-05', '1.24e-05', ...,
{ 'main::RUNTIME' => undef } ] }
+ for my $subscalled (values %{ $self->sub_call_lines }) {
+
+ for my $subname (keys %$subscalled) {
+ my $sc = $subscalled->{$subname};
+ $sc->[NYTP_SCi_INCL_RTIME] =
+ $sc->[NYTP_SCi_EXCL_RTIME] =
+ $sc->[NYTP_SCi_RECI_RTIME] = 0;
+
+ if (not $ENV{NYTPROF_TEST_SKIP_EVAL_NORM}) {
+ # normalize eval sequence numbers in anon sub names to 0
+ (my $newname = $subname) =~ s/ \( ((?:re_)?) eval \s \d+
\) /(${1}eval 0)/xg;
+ if ($newname ne $subname) {
+ warn "Normalizing $subname to $newname overwrote other
called-by data\n"
+ if $subscalled->{$newname};
+ $subscalled->{$newname} = delete
$subscalled->{$subname};
+ }
+ }
+ }
+
+ }
}
=======================================
--- /trunk/lib/Devel/NYTProf/SubInfo.pm Wed Apr 21 06:25:45 2010
+++ /trunk/lib/Devel/NYTProf/SubInfo.pm Mon May 3 13:49:06 2010
@@ -5,6 +5,7 @@
use Carp;
use List::Util qw(sum min max);
+use Data::Dumper;
use Devel::NYTProf::Constants qw(
NYTP_SIi_FID NYTP_SIi_FIRST_LINE NYTP_SIi_LAST_LINE
@@ -262,6 +263,11 @@
my $self = shift;
my $profile = $self->profile;
+ # normalize eval sequence numbers in anon sub names to 0
+ $self->[NYTP_SIi_SUB_NAME] =~ s/ \( ((?:re_)?) eval \s \d+ \)
/(${1}eval 0)/xg
+ if $self->[NYTP_SIi_SUB_NAME] =~ m/__ANON__/
+ && not $ENV{NYTPROF_TEST_SKIP_EVAL_NORM};
+
# zero subroutine inclusive time
$self->[NYTP_SIi_INCL_RTIME] = 0;
$self->[NYTP_SIi_EXCL_RTIME] = 0;
@@ -284,12 +290,26 @@
$callers->{$fid} = { map { $_ => shift @lines } 1...@lines };
}
- # zero per-call-location subroutine inclusive time
for my $sc (map { values %$_ } values %$callers) {
+ # zero per-call-location subroutine inclusive time
$sc->[NYTP_SCi_INCL_RTIME] =
$sc->[NYTP_SCi_EXCL_RTIME] =
$sc->[NYTP_SCi_RECI_RTIME] = 0;
- }
+
+ if (not $ENV{NYTPROF_TEST_SKIP_EVAL_NORM}) {
+ # normalize eval sequence numbers in anon sub names to 0
+ my $names = $sc->[NYTP_SCi_CALLING_SUB]||{};
+ for my $subname (keys %$names) {
+ (my $newname = $subname) =~ s/ \( ((?:re_)?) eval \s \d+
\) /(${1}eval 0)/xg;
+ next if $newname eq $subname;
+ warn "Normalizing $subname to $newname overwrote other
calling-sub data\n"
+ if $names->{$newname};
+ $names->{$newname} = delete $names->{$subname};
+ }
+ }
+
+ }
+ return $self->[NYTP_SIi_SUB_NAME];
}
sub dump {
=======================================
--- /trunk/t/40-savesrc.t Thu Mar 11 03:02:29 2010
+++ /trunk/t/40-savesrc.t Mon May 3 13:49:06 2010
@@ -33,7 +33,7 @@
my $lines_s = $fi_s->srclines_array;
isa_ok $lines_s, 'ARRAY', 'srclines_array should return an array
ref';
- my $fi_e = $profile->fileinfo_of('(eval 0)[-:1]');
+ my $fi_e = $profile->fileinfo_of('(eval 1)[-:1]');
isa_ok $fi_e, 'Devel::NYTProf::FileInfo', 'should have fileinfo
for "(eval 0)[-:1]"';
if ($env->{savesrc}) {
=======================================
--- /trunk/t/lib/NYTProfTest.pm Fri Apr 23 05:27:23 2010
+++ /trunk/t/lib/NYTProfTest.pm Mon May 3 13:49:06 2010
@@ -348,10 +348,11 @@
}
+# some tests use profile_this() in Devel::NYTProf::Run
sub run_perl_command {
my ($cmd, $show_stdout) = @_;
local $ENV{PERL5LIB} = $perl5lib;
- run_command("$this_perl $cmd", $show_stdout);
+ run_command("$this_perl -f $cmd", $show_stdout);
}
=======================================
--- /trunk/t/test22-strevala.rdt Wed Apr 21 04:41:03 2010
+++ /trunk/t/test22-strevala.rdt Mon May 3 13:49:06 2010
@@ -32,29 +32,31 @@
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 0)[test22-strevala.p:6]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 9 main::__ANON__[(eval 0)[test22-strevala.p:9]:1] [ 2
0 0 0 0 0 0 main::RUNTIME ]
+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 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 2 [ (eval 0)[test22-strevala.p:6] 1 6 2 2 0 0 ]
-fid_fileinfo 2 sub main::__ANON__[(eval 0)[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 0)[test22-strevala.p:6]:1] ]
+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 0)[test22-strevala.p:9] 1 9 3 2 0 0 ]
-fid_fileinfo 3 sub main::__ANON__[(eval 0)[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 0)[test22-strevala.p:9]:1] ]
+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 0)[test22-strevala.p:9] 1 9 4 2 0 0 ]
-fid_fileinfo 4 sub main::__ANON__[(eval 0)[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 0)[test22-strevala.p:9]:1] ]
+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 5 [ (eval 0)[test22-strevala.p:12] 1 12 5 2 0 0 ]
-fid_fileinfo 5 call 2 main::__ANON__[(eval 0)[(eval
0)[test22-strevala.p:12]:2]:1] [ 2 0 0 0 0 0 0 main::RUNTIME ]
+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 6 [ (eval 0)[(eval 0)[test22-strevala.p:12]:2] 5 2 6 2 0
0 ]
-fid_fileinfo 6 sub main::__ANON__[(eval 0)[(eval
0)[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 0)[(eval 0)[test22-strevala.p:12]:2]:1] ]
+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 0)[(eval 0)[test22-strevala.p:12]:2] 5 2 7 2 0
0 ]
-fid_fileinfo 7 sub main::__ANON__[(eval 0)[(eval
0)[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 0)[(eval 0)[test22-strevala.p:12]:2]:1] ]
+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_line_time 1 3 [ 0 1 ]
fid_line_time 1 6 [ 0 1 ]
fid_line_time 1 9 [ 0 2 ]
@@ -90,15 +92,19 @@
profile_modes fid_sub_time sub
sub_subinfo main::BEGIN [ 1 0 0 0 0 0 0 0 ]
sub_subinfo main::CORE:print [ 1 0 0 5 0 0 0 0 ]
-sub_subinfo main::CORE:print called_by 2 1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 0)[test22-strevala.p:6]:1] ]
-sub_subinfo main::CORE:print called_by 3 1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 0)[test22-strevala.p:9]:1] ]
-sub_subinfo main::CORE:print called_by 4 1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 0)[test22-strevala.p:9]:1] ]
-sub_subinfo main::CORE:print called_by 6 1 [ 1 0 0 0 0 0 0
main::__ANON__[(eval 0)[(eval 0)[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 0)[(eval 0)[test22-strevala.p:12]:2]:1] ]
+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::RUNTIME [ 1 1 1 0 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[(eval 0)[test22-strevala.p:12]:2]:1] [
6 1 1 2 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[(eval 0)[test22-strevala.p:12]:2]:1]
called_by 5 2 [ 2 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 0)[test22-strevala.p:6]:1] [ 2 1 1 1 0 0
0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[test22-strevala.p:6]:1] called_by 1 6
[ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::__ANON__[(eval 0)[test22-strevala.p:9]:1] [ 3 1 1 2 0 0
0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[test22-strevala.p:9]:1] called_by 1 9
[ 2 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 1)[test22-strevala.p:6]:1] [ 2 1 1 1 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 1 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 1 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 1 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 1 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 ]
=======================================
--- /trunk/t/test22-strevala.t Fri Feb 6 01:47:28 2009
+++ /trunk/t/test22-strevala.t Mon May 3 13:49:06 2010
@@ -3,4 +3,6 @@
use lib qw(t/lib);
use NYTProfTest;
+$ENV{NYTPROF_TEST_SKIP_EVAL_NORM} = 1;
+
run_test_group;
=======================================
--- /trunk/t/test24-strevalc.rdt Mon Apr 26 05:45:51 2010
+++ /trunk/t/test24-strevalc.rdt Mon May 3 13:49:06 2010
@@ -20,10 +20,11 @@
fid_block_time 5 1 [ 0 1 ]
fid_block_time 6 1 [ 0 1 ]
fid_block_time 7 1 [ 0 1 ]
-fid_block_time 8 2 [ 0 1 ]
-fid_block_time 9 2 [ 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 7 [ count 5 nested 2 merged 1 ]
fid_fileinfo 2 [ (eval 0)[test24-strevalc.p:7] 1 7 2 2 0 0 ]
fid_fileinfo 4 [ (eval 0)[test24-strevalc.p:7] 1 7 4 2 0 0 ]
@@ -33,9 +34,11 @@
fid_fileinfo 6 eval 1 [ count 1 nested 0 merged 0 ]
fid_fileinfo 7 [ (eval 0)[(eval 0)[test24-strevalc.p:7]:1] 6 1 7 2 0 0
]
fid_fileinfo 8 [ (eval 0)[test24-strevalc.p:7] 1 7 8 2 0 0 ]
-fid_fileinfo 8 sub main::__ANON__[(eval 0)[test24-strevalc.p:7]:1]
1-1
+fid_fileinfo 8 sub main::__ANON__[(eval 7)[test24-strevalc.p:7]:1]
1-1
+fid_fileinfo 8 call 1 main::__ANON__[(eval 7)[test24-strevalc.p:7]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
fid_fileinfo 9 [ (eval 0)[test24-strevalc.p:7] 1 7 9 2 0 0 ]
-fid_fileinfo 9 sub main::__ANON__[(eval 0)[test24-strevalc.p:7]:1]
1-1
+fid_fileinfo 9 sub main::__ANON__[(eval 8)[test24-strevalc.p:7]:1]
1-1
+fid_fileinfo 9 call 1 main::__ANON__[(eval 8)[test24-strevalc.p:7]:1] [ 1
0 0 0 0 0 0 main::RUNTIME ]
fid_line_time 1 2 [ 0 1 ]
fid_line_time 1 7 [ 0 2 ]
fid_line_time 2 1 [ 0 2 ]
@@ -43,8 +46,8 @@
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 2 [ 0 1 ]
-fid_line_time 9 2 [ 0 1 ]
+fid_line_time 8 1 [ 0 2 ]
+fid_line_time 9 1 [ 0 2 ]
fid_sub_time 1 2 [ 0 1 ]
fid_sub_time 1 7 [ 0 2 ]
fid_sub_time 2 1 [ 0 1 ]
@@ -52,10 +55,14 @@
fid_sub_time 5 1 [ 0 1 ]
fid_sub_time 6 1 [ 0 1 ]
fid_sub_time 7 1 [ 0 1 ]
-fid_sub_time 8 2 [ 0 1 ]
-fid_sub_time 9 2 [ 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 0 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[test24-strevalc.p:7]:1] [ 8 1 1 0 0 0
0 0 ]
+sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ]
+sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:7]:1] [ 8 1 1 1 0 0
0 0 ]
+sub_subinfo main::__ANON__[(eval 7)[test24-strevalc.p:7]:1] called_by 8 1
[ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::__ANON__[(eval 8)[test24-strevalc.p:7]:1] [ 9 1 1 1 0 0
0 0 ]
+sub_subinfo main::__ANON__[(eval 8)[test24-strevalc.p:7]:1] called_by 9 1
[ 1 0 0 0 0 0 0 main::RUNTIME ]
=======================================
--- /trunk/t/test24-strevalc.t Mon Apr 26 05:45:51 2010
+++ /trunk/t/test24-strevalc.t Mon May 3 13:49:06 2010
@@ -3,4 +3,6 @@
use lib qw(t/lib);
use NYTProfTest;
+$ENV{NYTPROF_TEST_SKIP_EVAL_NORM} = 1;
+
run_test_group;
=======================================
--- /trunk/t/test61-submerge.rdt Wed Apr 21 04:41:03 2010
+++ /trunk/t/test61-submerge.rdt Mon May 3 13:49:06 2010
@@ -28,17 +28,19 @@
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 0)[test61-submerge.p:8]:1] [ 3
0 0 0 0 0 0 main::RUNTIME ]
+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 2 [ (eval 0)[test61-submerge.p:8] 1 8 2 2 0 0 ]
-fid_fileinfo 2 sub main::__ANON__[(eval 0)[test61-submerge.p:8]:1]
1-1
-fid_fileinfo 2 call 1 main::foo [ 1 0 0 0 0 0 0 main::__ANON__[(eval
0)[test61-submerge.p:8]:1] ]
+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 0)[test61-submerge.p:8] 1 8 3 2 0 0 ]
-fid_fileinfo 3 sub main::__ANON__[(eval 0)[test61-submerge.p:8]:1]
1-1
-fid_fileinfo 3 call 1 main::foo [ 1 0 0 0 0 0 0 main::__ANON__[(eval
0)[test61-submerge.p:8]:1] ]
+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 0)[test61-submerge.p:8] 1 8 4 2 0 0 ]
-fid_fileinfo 4 sub main::__ANON__[(eval 0)[test61-submerge.p:8]:1]
1-1
-fid_fileinfo 4 call 1 main::foo [ 1 0 0 0 0 0 0 main::__ANON__[(eval
0)[test61-submerge.p:8]:1] ]
+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_line_time 1 4 [ 0 3 ]
fid_line_time 1 6 [ 0 1 ]
fid_line_time 1 8 [ 0 2 ]
@@ -64,9 +66,13 @@
sub_subinfo main::CORE:print [ 1 0 0 3 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 0 0 0 0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[test61-submerge.p:8]:1] [ 2 1 1 3 0 0
0 0 ]
-sub_subinfo main::__ANON__[(eval 0)[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] [ 2 1 1 1 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 1 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 1 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::foo [ 1 4 4 3 0 0 0 0 ]
-sub_subinfo main::foo called_by 2 1 [ 1 0 0 0 0 0 0 main::__ANON__[(eval
0)[test61-submerge.p:8]:1] ]
-sub_subinfo main::foo called_by 3 1 [ 1 0 0 0 0 0 0 main::__ANON__[(eval
0)[test61-submerge.p:8]:1] ]
-sub_subinfo main::foo called_by 4 1 [ 1 0 0 0 0 0 0 main::__ANON__[(eval
0)[test61-submerge.p:8]:1] ]
+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] ]
=======================================
--- /trunk/t/test61-submerge.t Fri Feb 6 01:47:28 2009
+++ /trunk/t/test61-submerge.t Mon May 3 13:49:06 2010
@@ -3,4 +3,6 @@
use lib qw(t/lib);
use NYTProfTest;
+$ENV{NYTPROF_TEST_SKIP_EVAL_NORM} = 1;
+
run_test_group;
--
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]
