Revision: 863 Author: tim.bunce Date: Sat Sep 26 15:57:33 2009 Log: subr_entry_setup() now always pushes a destructor onto the stack as a fallback incase the call is to an xsub that croaks. Determine name of sub being called before we enter it, so we have the name if it's an xsub that croaks (as a bonus we now see sub calls that die e.g. because the sub doesn't exist). Documented the findcaller option. Probably has rough edges, and perl-version sensitivities, but it's a good point to checkin.
http://code.google.com/p/perl-devel-nytprof/source/detail?r=863 Modified: /trunk/NYTProf.xs /trunk/lib/Devel/NYTProf/PgPLPerl.pm /trunk/lib/Devel/NYTProf.pm /trunk/t/test13.rdt /trunk/t/test14.rdt /trunk/t/test60-subname.p /trunk/t/test60-subname.rdt /trunk/t/test61-submerge.rdt ======================================= --- /trunk/NYTProf.xs Wed Sep 23 02:45:43 2009 +++ /trunk/NYTProf.xs Sat Sep 26 15:57:33 2009 @@ -2086,7 +2086,9 @@ return av; } -/* subroutine profiler subroutine entry structure */ +/* subroutine profiler subroutine entry structure. Represents a call + * from one sub to another (the arc between the nodes, if you like) + */ typedef struct subr_entry_st subr_entry_t; struct subr_entry_st { int already_counted; @@ -2119,8 +2121,11 @@ static void subr_entry_destroy(pTHX_ subr_entry_t *subr_entry) { - if (trace_level >= 6 || subr_entry->already_counted>1) { - logwarn("discarding subr_entry for %s::%s (seix %d->%d, already_counted %d)\n", + if ((trace_level >= 6 || subr_entry->already_counted>1) + /* ignore the typical second (fallback) destroy */ + && !(subr_entry->prev_subr_entry_ix == subr_entry_ix && subr_entry->already_counted==1) + ) { + logwarn("discarding subr_entry for %s::%s (seix %d->%d, ac%d)\n", subr_entry->called_subpkg_pv, (subr_entry->called_subnam_sv) ? SvPV_nolen(subr_entry->called_subnam_sv) @@ -2158,7 +2163,8 @@ AV *subr_call_av; if (subr_entry->called_subnam_sv == &PL_sv_undef) { - logwarn("xsub/builtin exited via an exception (which isn't handled yet)\n"); + if (trace_level) + logwarn("Don't know name of called sub, assuming xsub/builtin exited via an exception (which isn't handled yet)\n"); subr_entry->already_counted++; } @@ -2303,13 +2309,18 @@ } -static SV * -resolve_sub(pTHX_ SV *sv, GV **subname_gv_ptr) -{ - GV *gv; +static CV * +resolve_sub_to_cv(pTHX_ SV *sv, GV **subname_gv_ptr) +{ + GV *dummy_gv; HV *stash; CV *cv; + if (!subname_gv_ptr) + subname_gv_ptr = &dummy_gv; + else + *subname_gv_ptr = Nullgv; + /* copied from top of perl's pp_entersub */ /* modified to return either CV or else a GV */ /* or a NULL in cases that pp_entersub would croak */ @@ -2353,15 +2364,15 @@ break; case SVt_PVGV: if (!(cv = GvCVu((GV*)sv))) - cv = sv_2cv(sv, &stash, &gv, FALSE); - if (!cv) { /* would autoload in this situation */ - if (subname_gv_ptr) - *subname_gv_ptr = gv; + cv = sv_2cv(sv, &stash, subname_gv_ptr, FALSE); + if (!cv) /* would autoload in this situation */ return NULL; - } break; } - return (SV *)cv; + if (cv && !*subname_gv_ptr && CvGV(cv)) { + *subname_gv_ptr = CvGV(cv); + } + return cv; } @@ -2377,6 +2388,10 @@ si = PL_curstackinfo; cx = &si->si_cxstack[ix]; + if (trace_level >= 9) + warn("finding current_cv(%d,%p) - cx_type %d %s, si_type %d\n", + ix, si, CxTYPE(cx), block_type[CxTYPE(cx)], si->si_type); + /* the common case of finding the caller on the same stack */ if (CxTYPE(cx) == CXt_SUB || CxTYPE(cx) == CXt_FORMAT) return cx->blk_sub.cv; @@ -2396,7 +2411,7 @@ static I32 -subr_entry_setup(pTHX_ COP *prev_cop, subr_entry_t *clone_subr_entry) +subr_entry_setup(pTHX_ COP *prev_cop, subr_entry_t *clone_subr_entry, SV *subr_sv) { int saved_errno = errno; subr_entry_t *subr_entry; @@ -2404,6 +2419,7 @@ 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 */ @@ -2411,7 +2427,7 @@ subr_entry_ix = SSNEWa(sizeof(*subr_entry), MEM_ALIGNBYTES); subr_entry = subr_entry_ix_ptr(subr_entry_ix); if (subr_entry_ix <= prev_subr_entry_ix) { - logwarn("Something's very wrong!\n"); + logwarn("NYTProf: stack is confused!\n"); } Zero(subr_entry, 1, sizeof(subr_entry_t)); @@ -2422,8 +2438,20 @@ subr_entry->initial_overhead_ticks = cumulative_overhead_ticks; subr_entry->initial_subr_secs = cumulative_subr_secs; subr_entry->subr_call_seqn = ++cumulative_subr_seqn; - subr_entry->called_subnam_sv = &PL_sv_undef; /* see incr_sub_inclusive_time */ - subr_entry->called_is_xs = NULL; /* we don't know yet */ + + /* try to work out what sub's being called in advance + * mainly for xsubs because otherwise they're transparent + * because xsub calls don't get a new context + */ + 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)); + subr_entry->called_subnam_sv = newSVpv(GvNAME(called_gv), 0); + } + else { + subr_entry->called_subnam_sv = newSV(0); /* see incr_sub_inclusive_time */ + } + subr_entry->called_is_xs = NULL; /* work it out later */ file = OutCopFILE(prev_cop); subr_entry->caller_fid = (file == last_executed_fileptr) @@ -2500,13 +2528,21 @@ } if (trace_level >= 4) - logwarn("Making sub call at %u:%d from %s::%s %s (seix %d->%d)\n", + logwarn("Making sub call (%s) at %u:%d from %s::%s %s (seix %d->%d)\n", + SvPV_nolen(subr_sv), subr_entry->caller_fid, subr_entry->caller_line, subr_entry->caller_subpkg_pv, SvPV_nolen(subr_entry->caller_subnam_sv), found_caller_by, (int)prev_subr_entry_ix, (int)subr_entry_ix ); + /* This is our safety-net destructor. For perl subs an identical destructor + * will be pushed onto the stack inside the scope we're interested in. + * That destructor will be more accurate than this one. This one is here + * mainly to catch exceptions thrown from xs subs and slowops. + */ + save_destructor_x(incr_sub_inclusive_time_ix, INT2PTR(void *, (IV)subr_entry_ix)); + SETERRNO(saved_errno, 0); return subr_entry_ix; @@ -2539,7 +2575,6 @@ SV *sub_sv = *SP; I32 this_subr_entry_ix = 0; /* local copy (needed for goto) */ - SV *called_subnam_sv; char *stash_name = NULL; char *is_xs; subr_entry_t *subr_entry; @@ -2583,7 +2618,7 @@ */ called_cv = NULL; - this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, NULL); + this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, NULL, sub_sv); /* This call may exit via an exception, in which case the * remaining code below doesn't get executed and the sub call @@ -2634,7 +2669,7 @@ /* now we're in goto'd sub, mortalize the REFCNT_inc's done above */ sv_2mortal(goto_subr_entry.caller_subnam_sv); sv_2mortal(goto_subr_entry.called_subnam_sv); - this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, &goto_subr_entry); + this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, &goto_subr_entry, sub_sv); } /* push a destructor hook onto the context stack to ensure we account @@ -2644,7 +2679,6 @@ subr_entry = subr_entry_ix_ptr(this_subr_entry_ix); - called_subnam_sv = newSV(0); if (is_slowop) { /* pretend builtins are xsubs in the same package * but with "CORE:" (one colon) prepended to the name. @@ -2654,11 +2688,11 @@ is_xs = "sop"; if (profile_slowops == 1) { /* 1 == put slowops into 1 package */ stash_name = "CORE"; - sv_setpv(called_subnam_sv, slowop_name); + sv_setpv(subr_entry->called_subnam_sv, slowop_name); } else { /* 2 == put slowops into multiple packages */ stash_name = CopSTASHPV(PL_curcop); - sv_setpvf(called_subnam_sv, "CORE:%s", slowop_name); + sv_setpvf(subr_entry->called_subnam_sv, "CORE:%s", slowop_name); } subr_entry->called_cv_depth = 1; /* an approximation for slowops */ } @@ -2677,14 +2711,14 @@ /* determine the original fully qualified name for sub */ /* CV or NULL */ GV *gv = NULL; - called_cv = (CV *)resolve_sub(aTHX_ sub_sv, &gv); + called_cv = resolve_sub_to_cv(aTHX_ sub_sv, &gv); if (!called_cv && gv) { /* XXX no test case for this */ stash_name = HvNAME(GvSTASH(gv)); - sv_setpv(called_subnam_sv, GvNAME(gv)); + sv_setpv(subr_entry->called_subnam_sv, GvNAME(gv)); if (trace_level >= 0) logwarn("Assuming called sub is named %s::%s at %s line %d (please report as a bug)\n", - stash_name, SvPV_nolen(called_subnam_sv), + stash_name, SvPV_nolen(subr_entry->called_subnam_sv), OutCopFILE(prev_cop), (int)CopLINE(prev_cop)); } is_xs = "xsub"; @@ -2698,7 +2732,7 @@ * package, so we dig to find the original package */ stash_name = HvNAME(GvSTASH(gv)); - sv_setpv(called_subnam_sv, GvNAME(gv)); + sv_setpv(subr_entry->called_subnam_sv, GvNAME(gv)); } else if (trace_level >= 0) { logwarn("I'm confused about CV %p called as %s at %s line %d (please report as a bug)\n", @@ -2710,17 +2744,17 @@ } /* called_subnam_sv should have been set by now - else we're getting desperate */ - if (!SvOK(called_subnam_sv)) { + if (!SvOK(subr_entry->called_subnam_sv)) { const char *what = (is_xs) ? is_xs : "sub"; if (!called_cv) { /* should never get here as pp_entersub would have croaked */ logwarn("unknown entersub %s '%s' (please report this as a bug)\n", what, SvPV_nolen(sub_sv)); stash_name = CopSTASHPV(PL_curcop); - sv_setpvf(called_subnam_sv, "__UNKNOWN__[%s,%s])", what, SvPV_nolen(sub_sv)); + sv_setpvf(subr_entry->called_subnam_sv, "__UNKNOWN__[%s,%s])", what, SvPV_nolen(sub_sv)); } else { /* unnamed CV, e.g. seen in mod_perl/Class::MOP. XXX do better? */ stash_name = HvNAME(CvSTASH(called_cv)); - sv_setpvf(called_subnam_sv, "__UNKNOWN__[%s,0x%p]", what, called_cv); + sv_setpvf(subr_entry->called_subnam_sv, "__UNKNOWN__[%s,0x%p]", what, called_cv); if (trace_level) logwarn("unknown entersub %s assumed to be anon called_cv '%s'\n", what, SvPV_nolen(sub_sv)); @@ -2733,12 +2767,13 @@ 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_subnam_sv = called_subnam_sv; 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") && strEQ(SvPV_nolen(called_subnam_sv), "_INIT")) { + if (is_xs && *stash_name == 'D' && strEQ(stash_name,"DB") + && strEQ(SvPV_nolen(subr_entry->called_subnam_sv), "_INIT") + ) { subr_entry->already_counted++; goto skip_sub_profile; } @@ -2748,7 +2783,7 @@ 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(called_subnam_sv), + (is_xs) ? is_xs : "sub", stash_name, 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, @@ -4427,13 +4462,19 @@ PROTOTYPES: DISABLE void -example_xsub(char *unused="", char *action="") +example_xsub(char *unused="", SV *action=Nullsv, SV *arg=Nullsv) CODE: - if (!action || !*action) + if (!action) XSRETURN(0); - if (strEQ(action,"die")) + if (SvROK(action) && SvTYPE(SvRV(action))==SVt_PVCV) { + /* perl <= 5.8.8 doesn't use OP_ENTERSUB so won't be seen by NYTProf */ + call_sv(action, G_VOID|G_DISCARD); + } + else if (strEQ(SvPV_nolen(action),"eval")) + eval_pv(SvPV_nolen(arg), TRUE); + else if (strEQ(SvPV_nolen(action),"die")) croak("example_xsub(die)"); - logwarn("example_xsub: unknown action '%s'\n", action); + logwarn("example_xsub: unknown action '%s'\n", SvPV_nolen(action)); void example_xsub_eval(...) ======================================= --- /trunk/lib/Devel/NYTProf/PgPLPerl.pm Sat Sep 19 14:03:28 2009 +++ /trunk/lib/Devel/NYTProf/PgPLPerl.pm Sat Sep 26 15:57:33 2009 @@ -27,6 +27,9 @@ return $obj->$orig_share_from(@_); }; +#require DynaLoader; +#warn DynaLoader::dl_find_symbol(0, "error_context_stack"); + require Devel::NYTProf; # init profiler 1; @@ -50,6 +53,7 @@ This module allows PL/Perl functions inside PostgreSQL database to be profiled with C<Devel::NYTProf>. + =head1 LIMITATIONS The perl functions defined with the C<plperl> language (not C<plperlu>) don't @@ -66,7 +70,7 @@ =head1 COPYRIGHT AND LICENSE - Copyright (C) 2008 by Tim Bunce. + Copyright (C) 2009 by Tim Bunce. This library is free software; you can redistribute it and/or modify it under the same terms as Perl itself, either Perl version 5.8.8 or, ======================================= --- /trunk/lib/Devel/NYTProf.pm Wed Sep 2 07:21:11 2009 +++ /trunk/lib/Devel/NYTProf.pm Sat Sep 26 15:57:33 2009 @@ -355,6 +355,12 @@ NYTProf is the only line-level profiler to measure these times correctly. The profiler is fast enough that you shouldn't need to disable this feature. +=head2 findcaller=1 + +Force NYTProf to recalculate the name of the caller of the each sub instead of +'inheriting' the name calculated when the caller was entered. (Rarely needed, +but might be useful in some odd cases.) + =head2 use_db_sub=1 Set to 1 to enable use of the traditional DB::DB() subroutine to perform ======================================= --- /trunk/t/test13.rdt Thu Aug 6 19:20:50 2009 +++ /trunk/t/test13.rdt Sat Sep 26 15:57:33 2009 @@ -34,6 +34,7 @@ fid_fileinfo 1 call 12 main::CORE:print [ 1 0 0 0 0 0 0 main::baz ] fid_fileinfo 1 call 13 main::foo [ 1 0 0 0 0 0 0 main::baz ] fid_fileinfo 1 call 14 main::foo [ 1 0 0 0 0 0 0 main::baz ] +fid_fileinfo 1 call 15 main::x [ 1 0 0 0 0 0 0 main::baz ] fid_fileinfo 1 call 20 main::bar [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 1 call 21 main::baz [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 1 eval 19 [ 1 0 ] @@ -75,3 +76,5 @@ sub_subinfo main::foo called_by 1 13 [ 1 0 0 0 0 0 0 main::baz ] sub_subinfo main::foo called_by 1 14 [ 1 0 0 0 0 0 0 main::baz ] sub_subinfo main::foo called_by 2 1 [ 1 0 0 0 0 0 0 main::RUNTIME ] +sub_subinfo main::x [ undef undef undef 1 0 0 0 0 ] +sub_subinfo main::x called_by 1 15 [ 1 0 0 0 0 0 0 main::baz ] ======================================= --- /trunk/t/test14.rdt Thu Aug 6 19:20:50 2009 +++ /trunk/t/test14.rdt Sat Sep 26 15:57:33 2009 @@ -60,8 +60,8 @@ 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 ] -sub_subinfo test14::bar called_by 3 51 [ 1 0 0 0 0 0 0 main::RUNTIME ] +sub_subinfo test14::bar called_by 3 116 [ 1 0 0 0 0 0 0 main::RUNTIME ] sub_subinfo test14::foo [ 2 12 14 1 0 0 0 0 ] -sub_subinfo test14::foo called_by 3 51 [ 1 0 0 0 0 0 0 main::RUNTIME ] +sub_subinfo test14::foo called_by 3 116 [ 1 0 0 0 0 0 0 main::RUNTIME ] sub_subinfo test14::pre [ 2 8 8 1 0 0 0 0 ] sub_subinfo test14::pre called_by 1 17 [ 1 0 0 0 0 0 0 main::RUNTIME ] ======================================= --- /trunk/t/test60-subname.p Wed Jul 15 05:44:35 2009 +++ /trunk/t/test60-subname.p Sat Sep 26 15:57:33 2009 @@ -26,3 +26,9 @@ # affects AUTOLOAD subs. sub launch { goto &$subname } launch("foo"); + +# return from xsub call via an exception +# should correctly record the name of the xsub +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 Thu Aug 6 19:20:50 2009 +++ /trunk/t/test60-subname.rdt Sat Sep 26 15:57:33 2009 @@ -22,11 +22,15 @@ 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_fileinfo 1 [ test60-subname.p 1 2 0 0 ] fid_fileinfo 1 sub main::BEGIN 2-2 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 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 ] @@ -35,6 +39,7 @@ 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 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 @@ -48,6 +53,9 @@ 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_sub_time 1 5 [ 0 1 ] fid_sub_time 1 9 [ 0 1 ] fid_sub_time 1 12 [ 0 1 ] @@ -58,20 +66,25 @@ 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 ] profile_modes fid_block_time block profile_modes fid_line_time line profile_modes fid_sub_time sub sub_subinfo Devel::NYTProf::Test::example_sub [ 2 13 13 0 0 0 0 0 ] -sub_subinfo Devel::NYTProf::Test::example_xsub [ 2 0 0 6 0 0 0 0 ] +sub_subinfo Devel::NYTProf::Test::example_xsub [ 2 0 0 7 0 0 0 0 ] sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 5 [ 1 0 0 0 0 0 0 main::RUNTIME ] sub_subinfo Devel::NYTProf::Test::example_xsub called_by 1 9 [ 1 0 0 0 0 0 0 main::RUNTIME ] 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 main::BEGIN [ 1 2 2 0 0 0 0 0 ] 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 0 0 0 0 0 ] ======================================= --- /trunk/t/test61-submerge.rdt Thu Aug 6 19:20:50 2009 +++ /trunk/t/test61-submerge.rdt Sat Sep 26 15:57:33 2009 @@ -28,11 +28,11 @@ 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 3 [ (eval 0)[test61-submerge.p:8] 1 8 3 2 0 0 ] +fid_fileinfo 3 sub main::CORE:print 0-0 +fid_fileinfo 3 sub main::RUNTIME 1-1 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 4 [ (eval 0)[test61-submerge.p:8] 1 8 4 2 0 0 ] -fid_fileinfo 4 sub main::CORE:print 0-0 -fid_fileinfo 4 sub main::RUNTIME 1-1 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_line_time 1 4 [ 0 3 ] @@ -51,9 +51,9 @@ 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::CORE:print [ 4 0 0 3 0 0 0 0 ] +sub_subinfo main::CORE:print [ 3 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 [ 4 1 1 0 0 0 0 0 ] +sub_subinfo main::RUNTIME [ 3 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::foo [ 1 4 4 3 0 0 0 0 ] --~--~---------~--~----~------------~-------~--~----~ 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] -~----------~----~----~----~------~----~------~--~---
