[perl-devel-nytprof] r889 committed - Fixed handling of slowops that exit via an exceptions....
codesite...@google.com
Author: tim.bunce
Date: Wed Oct 28 08:22:30 2009
Log: Fixed handling of slowops that exit via an exceptions.
Tidied some code and logging.
Resync'd affected test results.
http://code.google.com/p/perl-devel-nytprof/source/detail?r=889
Modified:
/trunk/NYTProf.xs
/trunk/t/test14.rdt
/trunk/t/test60-subname.p
/trunk/t/test60-subname.rdt
/trunk/t/test62-subcaller1.rdt
=======================================
--- /trunk/NYTProf.xs Wed Oct 28 06:19:29 2009
+++ /trunk/NYTProf.xs Wed Oct 28 08:22:30 2009
@@ -2454,7 +2454,6 @@
subr_entry_t *caller_subr_entry;
char *found_caller_by;
char *file;
- GV *called_gv = Nullgv;
/* allocate struct to save stack (very efficient) */
/* XXX "warning: cast from pointer to integer of different size" with
use64bitall=define */
@@ -2478,7 +2477,8 @@
* mainly for xsubs because otherwise they're transparent
* because xsub calls don't get a new context
*/
- if (op_type == OP_ENTERSUB) {
+ if (op_type == OP_ENTERSUB || op_type == OP_GOTO) {
+ GV *called_gv = Nullgv;
subr_entry->called_cv = resolve_sub_to_cv(aTHX_ subr_sv,
&called_gv);
if (called_gv) {
subr_entry->called_subpkg_pv = HvNAME(GvSTASH(called_gv));
@@ -2487,11 +2487,23 @@
else {
subr_entry->called_subnam_sv = newSV(0); /* see
incr_sub_inclusive_time */
}
- }
- else {
- subr_entry->called_subnam_sv = newSV(0); /* see
incr_sub_inclusive_time */
- }
- subr_entry->called_is_xs = NULL; /* work it out later */
+ subr_entry->called_is_xs = NULL; /* work it out later */
+ }
+ else { /* slowop */
+
+ /* pretend slowops (builtins) are xsubs */
+ const char *slowop_name = PL_op_name[op_type];
+ if (profile_slowops == 1) { /* 1 == put slowops into 1 package */
+ subr_entry->called_subpkg_pv = "CORE";
+ subr_entry->called_subnam_sv = newSVpv(slowop_name, 0);
+ }
+ else { /* 2 == put slowops into multiple
packages */
+ subr_entry->called_subpkg_pv = CopSTASHPV(PL_curcop);
+ subr_entry->called_subnam_sv = newSVpvf("CORE:%s",
slowop_name);
+ }
+ subr_entry->called_cv_depth = 1; /* an approximation for slowops */
+ subr_entry->called_is_xs = "sop";
+ }
file = OutCopFILE(prev_cop);
subr_entry->caller_fid = (file == last_executed_fileptr)
@@ -2568,7 +2580,8 @@
}
if (trace_level >= 4) {
- logwarn("Making sub call at %u:%d from %s::%s %s (seix %d->%d)\n",
+ logwarn(" >> %s at %u:%d from %s::%s %s (seix %d->%d)\n",
+ PL_op_name[op_type],
subr_entry->caller_fid, subr_entry->caller_line,
subr_entry->caller_subpkg_pv,
SvPV_nolen(subr_entry->caller_subnam_sv),
@@ -2615,8 +2628,6 @@
SV *sub_sv = *SP;
I32 this_subr_entry_ix = 0; /* local copy (needed for goto) */
- char *stash_name = NULL;
- char *is_xs;
subr_entry_t *subr_entry;
/* pre-conditions */
@@ -2721,23 +2732,12 @@
subr_entry = subr_entry_ix_ptr(this_subr_entry_ix);
if (is_slowop) {
- /* pretend builtins are xsubs in the same package
- * but with "CORE:" (one colon) prepended to the name.
- */
- const char *slowop_name = OP_NAME_safe(PL_op);
- called_cv = NULL;
- is_xs = "sop";
- if (profile_slowops == 1) { /* 1 == put slowops into 1 package */
- stash_name = "CORE";
- sv_setpv(subr_entry->called_subnam_sv, slowop_name);
- }
- else { /* 2 == put slowops into multiple
packages */
- stash_name = CopSTASHPV(PL_curcop);
- sv_setpvf(subr_entry->called_subnam_sv, "CORE:%s",
slowop_name);
- }
- subr_entry->called_cv_depth = 1; /* an approximation for slowops */
+ /* already fully handled by subr_entry_setup */
}
else {
+ char *stash_name = NULL;
+ char *is_xs = NULL;
+
if (op_type == OP_GOTO) {
/* use the called_cv that was the arg to the goto op */
is_xs = (CvISXSUB(called_cv)) ? "xsub" : NULL;
@@ -2803,16 +2803,18 @@
if (trace_level)
sv_dump(sub_sv);
}
+ subr_entry->called_subpkg_pv = stash_name;
/* if called was xsub then we've already left it, so use depth+1 */
subr_entry->called_cv_depth = (called_cv) ?
CvDEPTH(called_cv)+(is_xs?1:0) : 0;
- }
- subr_entry->called_subpkg_pv = stash_name;
- subr_entry->called_cv = called_cv;
- subr_entry->called_is_xs = is_xs;
+ subr_entry->called_cv = called_cv;
+ subr_entry->called_is_xs = is_xs;
+ }
/* ignore our own DB::_INIT sub - only shows up with 5.8.9+ & 5.10.1+
*/
- if (is_xs && *stash_name == 'D' && strEQ(stash_name,"DB")
+ if (subr_entry->called_is_xs
+ && *subr_entry->called_subpkg_pv == 'D'
+ && strEQ(subr_entry->called_subpkg_pv,"DB")
&& strEQ(SvPV_nolen(subr_entry->called_subnam_sv), "_INIT")
) {
subr_entry->already_counted++;
@@ -2824,7 +2826,8 @@
if (trace_level >= 2) {
logwarn(" ->%4s %s::%s from %s::%s (d%d, oh %"NVff"t,
sub %"NVff"s) #%lu\n",
- (is_xs) ? is_xs : "sub", stash_name,
SvPV_nolen(subr_entry->called_subnam_sv),
+ (subr_entry->called_is_xs) ? subr_entry->called_is_xs : "sub",
+ subr_entry->called_subpkg_pv,
SvPV_nolen(subr_entry->called_subnam_sv),
subr_entry->caller_subpkg_pv,
SvPV_nolen(subr_entry->caller_subnam_sv),
subr_entry->called_cv_depth,
subr_entry->initial_overhead_ticks,
@@ -2833,7 +2836,7 @@
);
}
- if (is_xs) {
+ if (subr_entry->called_is_xs) {
/* for xsubs/builtins we've already left the sub, so end the
timing now
* rather than wait for the calling scope to get cleaned up.
*/
=======================================
--- /trunk/t/test14.rdt Thu Oct 22 09:05:10 2009
+++ /trunk/t/test14.rdt Wed Oct 28 08:22:30 2009
@@ -23,7 +23,6 @@
fid_block_time 2 20 [ 0 1 ]
fid_fileinfo 1 [ test14.p 1 2 0 0 ]
fid_fileinfo 1 sub main::BEGIN 16-16
-fid_fileinfo 1 sub main::CORE:require 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
fid_fileinfo 1 call 17 test14::pre [ 1 0 0 0 0 0 0 main::RUNTIME ]
fid_fileinfo 1 call 18 AutoLoader::AUTOLOAD [ 1 0 0 0 0 0 0 main::RUNTIME ]
@@ -58,7 +57,6 @@
profile_modes fid_line_time line
profile_modes fid_sub_time sub
sub_subinfo main::BEGIN [ 1 16 16 0 0 0 0 0 ]
-sub_subinfo main::CORE:require [ 1 0 0 2 0 0 0 0 ]
sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ]
sub_subinfo test14::BEGIN [ 2 2 2 0 0 0 0 0 ]
sub_subinfo test14::bar [ 2 16 18 1 0 0 0 0 ]
=======================================
--- /trunk/t/test60-subname.p Sat Sep 26 15:57:33 2009
+++ /trunk/t/test60-subname.p Wed Oct 28 08:22:30 2009
@@ -18,9 +18,12 @@
my $subname = "Devel::NYTProf::Test::example_xsub";
&$subname("foo");
-# call builtin (will be recorded if slowops option set)
+# call builtin
wait();
+# call builtin that exits via an exception
+eval { open my $f, '<&', 'nonesuch' }; # $@ "Bad filehandle: nonesuch"
+
# XXX currently goto isn't noticed by the profiler
# it's as if the call never happened. This most frequently
# affects AUTOLOAD subs.
@@ -32,3 +35,4 @@
sub will_die { die "foo\n" }
eval { example_xsub(0, \&will_die); 1; };
warn "\$@ not set ($@)" if $@ ne "foo\n";
+
=======================================
--- /trunk/t/test60-subname.rdt Sun Oct 25 02:46:30 2009
+++ /trunk/t/test60-subname.rdt Wed Oct 28 08:22:30 2009
@@ -20,27 +20,30 @@
fid_block_time 1 18 [ 0 1 ]
fid_block_time 1 19 [ 0 1 ]
fid_block_time 1 22 [ 0 1 ]
-fid_block_time 1 27 [ 0 1 ]
-fid_block_time 1 28 [ 0 1 ]
-fid_block_time 1 32 [ 0 1 ]
-fid_block_time 1 33 [ 0 2 ]
-fid_block_time 1 34 [ 0 1 ]
+fid_block_time 1 25 [ 0 2 ]
+fid_block_time 1 30 [ 0 1 ]
+fid_block_time 1 31 [ 0 1 ]
+fid_block_time 1 35 [ 0 1 ]
+fid_block_time 1 36 [ 0 2 ]
+fid_block_time 1 37 [ 0 1 ]
fid_fileinfo 1 [ test60-subname.p 1 2 0 0 ]
fid_fileinfo 1 sub main::BEGIN 2-2
+fid_fileinfo 1 sub main::CORE:open 0-0
fid_fileinfo 1 sub main::CORE:wait 0-0
fid_fileinfo 1 sub main::RUNTIME 1-1
-fid_fileinfo 1 sub main::launch 27-27
-fid_fileinfo 1 sub main::will_die 32-32
+fid_fileinfo 1 sub main::launch 30-30
+fid_fileinfo 1 sub main::will_die 35-35
fid_fileinfo 1 call 5 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
fid_fileinfo 1 call 9 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
fid_fileinfo 1 call 12 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
fid_fileinfo 1 call 16 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
fid_fileinfo 1 call 19 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
fid_fileinfo 1 call 22 main::CORE:wait [ 1 0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 27 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
-fid_fileinfo 1 call 28 main::launch [ 1 0 0 0 0 0 0 main::RUNTIME ]
-fid_fileinfo 1 call 33 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
-fid_fileinfo 1 call 33 main::will_die [ 1 0 0 0 0 0 0
Devel::NYTProf::Test::example_xsub ]
+fid_fileinfo 1 call 25 main::CORE:open [ 1 0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 1 call 30 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
+fid_fileinfo 1 call 31 main::launch [ 1 0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 1 call 36 Devel::NYTProf::Test::example_xsub [ 1 0 0 0 0 0 0
main::RUNTIME ]
+fid_fileinfo 1 call 36 main::will_die [ 1 0 0 0 0 0 0
Devel::NYTProf::Test::example_xsub ]
fid_fileinfo 2 [ Devel/NYTProf/Test.pm 2 4 0 0 ]
fid_fileinfo 2 sub Devel::NYTProf::Test::example_sub 13-13
fid_fileinfo 2 sub Devel::NYTProf::Test::example_xsub 0-0
@@ -52,11 +55,12 @@
fid_line_time 1 18 [ 0 1 ]
fid_line_time 1 19 [ 0 1 ]
fid_line_time 1 22 [ 0 1 ]
-fid_line_time 1 27 [ 0 1 ]
-fid_line_time 1 28 [ 0 1 ]
-fid_line_time 1 32 [ 0 1 ]
-fid_line_time 1 33 [ 0 2 ]
-fid_line_time 1 34 [ 0 1 ]
+fid_line_time 1 25 [ 0 2 ]
+fid_line_time 1 30 [ 0 1 ]
+fid_line_time 1 31 [ 0 1 ]
+fid_line_time 1 35 [ 0 1 ]
+fid_line_time 1 36 [ 0 2 ]
+fid_line_time 1 37 [ 0 1 ]
fid_sub_time 1 5 [ 0 1 ]
fid_sub_time 1 9 [ 0 1 ]
fid_sub_time 1 12 [ 0 1 ]
@@ -65,11 +69,12 @@
fid_sub_time 1 18 [ 0 1 ]
fid_sub_time 1 19 [ 0 1 ]
fid_sub_time 1 22 [ 0 1 ]
-fid_sub_time 1 27 [ 0 1 ]
-fid_sub_time 1 28 [ 0 1 ]
-fid_sub_time 1 32 [ 0 1 ]
-fid_sub_time 1 33 [ 0 2 ]
-fid_sub_time 1 34 [ 0 1 ]
+fid_sub_time 1 25 [ 0 2 ]
+fid_sub_time 1 30 [ 0 1 ]
+fid_sub_time 1 31 [ 0 1 ]
+fid_sub_time 1 35 [ 0 1 ]
+fid_sub_time 1 36 [ 0 2 ]
+fid_sub_time 1 37 [ 0 1 ]
profile_modes fid_block_time block
profile_modes fid_line_time line
profile_modes fid_sub_time sub
@@ -80,13 +85,15 @@
sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 12 [ 1 0 0 0 0
0 0 main::RUNTIME ]
sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 16 [ 1 0 0 0 0
0 0 main::RUNTIME ]
sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 19 [ 1 0 0 0 0
0 0 main::RUNTIME ]
-sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 27 [ 1 0 0 0 0
0 0 main::RUNTIME ]
-sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 33 [ 1 0 0 0 0
0 0 main::RUNTIME ]
+sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 30 [ 1 0 0 0 0
0 0 main::RUNTIME ]
+sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 36 [ 1 0 0 0 0
0 0 main::RUNTIME ]
sub_subinfo main::BEGIN [ 1 2 2 0 0 0 0 0 ]
+sub_subinfo main::CORE:open [ 1 0 0 1 0 0 0 0 ]
+sub_subinfo main::CORE:open called_by 1 25 [ 1 0 0 0 0 0 0 main::RUNTIME ]
sub_subinfo main::CORE:wait [ 1 0 0 1 0 0 0 0 ]
sub_subinfo main::CORE:wait called_by 1 22 [ 1 0 0 0 0 0 0 main::RUNTIME ]
sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ]
-sub_subinfo main::launch [ 1 27 27 1 0 0 0 0 ]
-sub_subinfo main::launch called_by 1 28 [ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo main::will_die [ 1 32 32 1 0 0 0 0 ]
-sub_subinfo main::will_die called_by 1 33 [ 1 0 0 0 0 0 0
Devel::NYTProf::Test::example_xsub ]
+sub_subinfo main::launch [ 1 30 30 1 0 0 0 0 ]
+sub_subinfo main::launch called_by 1 31 [ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo main::will_die [ 1 35 35 1 0 0 0 0 ]
+sub_subinfo main::will_die called_by 1 36 [ 1 0 0 0 0 0 0
Devel::NYTProf::Test::example_xsub ]
=======================================
--- /trunk/t/test62-subcaller1.rdt Sun Oct 25 02:46:30 2009
+++ /trunk/t/test62-subcaller1.rdt Wed Oct 28 08:22:30 2009
@@ -48,7 +48,7 @@
fid_fileinfo 2 sub Devel::NYTProf::Test::CORE:require 0-0
fid_fileinfo 2 sub Devel::NYTProf::Test::example_sub 13-13
fid_fileinfo 2 call 7 Devel::NYTProf::Test::CORE:require [ 1 0 0 0 0 0 0
main::RUNTIME ]
-fid_fileinfo 2 call 8 main::CORE:require [ 1 0 0 0 0 0 0 main::RUNTIME ]
+fid_fileinfo 2 call 8 Devel::NYTProf::Test::CORE:require [ 1 0 0 0 0 0 0
main::RUNTIME ]
fid_fileinfo 3 [ Exporter.pm 3 2 0 0 ]
fid_line_time 1 4 [ 0 1 ]
fid_line_time 1 6 [ 0 1 ]
@@ -87,8 +87,9 @@
profile_modes fid_block_time block
profile_modes fid_line_time line
profile_modes fid_sub_time sub
-sub_subinfo Devel::NYTProf::Test::CORE:require [ 2 0 0 1 0 0 0 0 ]
+sub_subinfo Devel::NYTProf::Test::CORE:require [ 2 0 0 2 0 0 0 0 ]
sub_subinfo Devel::NYTProf::Test::CORE:require called_by 2 7 [ 1 0 0 0 0 0
0 main::RUNTIME ]
+sub_subinfo Devel::NYTProf::Test::CORE:require called_by 2 8 [ 1 0 0 0 0 0
0 main::RUNTIME ]
sub_subinfo Devel::NYTProf::Test::example_sub [ 2 13 13 0 0 0 0 0 ]
sub_subinfo Devel::NYTProf::Test::example_xsub [ undef undef undef 2 0 0 0
0 ]
sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 17 [ 1 0 0 0 0
0 0 main::RUNTIME ]
@@ -100,9 +101,8 @@
sub_subinfo MyTie::TIESCALAR [ 1 6 6 1 0 0 0 0 ]
sub_subinfo MyTie::TIESCALAR called_by 1 11 [ 1 0 0 0 0 0 0 main::NULL ]
sub_subinfo main::BEGIN [ 1 0 0 0 0 0 0 0 ]
-sub_subinfo main::CORE:require [ 1 0 0 2 0 0 0 0 ]
+sub_subinfo main::CORE:require [ 1 0 0 1 0 0 0 0 ]
sub_subinfo main::CORE:require called_by 1 16 [ 1 0 0 0 0 0 0
main::RUNTIME ]
-sub_subinfo main::CORE:require called_by 2 8 [ 1 0 0 0 0 0 0 main::RUNTIME
]
sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ]
sub_subinfo main::use_eval_arg [ 1 21 21 1 0 0 0 0 ]
sub_subinfo main::use_eval_arg called_by 1 22 [ 1 0 0 0 0 0 0
main::RUNTIME ]