Revision: 889 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 ] --~--~---------~--~----~------------~-------~--~----~ 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] -~----------~----~----~----~------~----~------~--~---
