Revision: 870 Author: tim.bunce Date: Thu Oct 22 07:42:40 2009 Log: Fixed zeroing of subr_entry! Fixed compiler warnings. Don't call resolve_sub_to_cv() for non-OP_ENTERSUB calls Disabled OP_SUBSTCONT fow now - needs special handling like OP_GOTO Synced affected tests. (All tests pass for the perl version I'm using - but some will fail on others)
http://code.google.com/p/perl-devel-nytprof/source/detail?r=870 Modified: /trunk/Changes /trunk/NYTProf.xs /trunk/slowops.h /trunk/t/22-readstream.t /trunk/t/test12.rdt /trunk/t/test14.rdt /trunk/t/test21-streval3.rdt /trunk/t/test30-fork-0.rdt /trunk/t/test80-recurs.rdt ======================================= --- /trunk/Changes Fri Oct 2 14:39:08 2009 +++ /trunk/Changes Thu Oct 22 07:42:40 2009 @@ -9,6 +9,7 @@ XXX subroutine profiler docs need update XXX note here and doc goto behaviour XXX update and test JIT +XXX OP_SUBSTCONT Note: The file format has changed. Old files can't be read. ======================================= --- /trunk/NYTProf.xs Sat Sep 26 15:57:33 2009 +++ /trunk/NYTProf.xs Thu Oct 22 07:42:40 2009 @@ -2145,7 +2145,7 @@ subr_entry_ix = subr_entry->prev_subr_entry_ix; else logwarn("skipped attempt to raise subr_entry_ix from %d to %d\n", - subr_entry_ix, subr_entry->prev_subr_entry_ix); + (int)subr_entry_ix, (int)subr_entry->prev_subr_entry_ix); } @@ -2267,14 +2267,14 @@ } if (trace_level >= 3) - logwarn(" <- %s %"NVff"s excl = %"NVff"s incl - %"NVff"s (%g-%g), oh %g-%g=%gt, d%d @%d:%d #%lu\n", + logwarn(" <- %s %"NVff"s excl = %"NVff"s incl - %"NVff"s (%g-%g), oh %g-%g=%gt, d%d @%d:%d #%lu %p\n", called_subname_pv, excl_subr_sec, incl_subr_sec, called_sub_secs, cumulative_subr_secs, subr_entry->initial_subr_secs, cumulative_overhead_ticks, subr_entry->initial_overhead_ticks, overhead_ticks, (int)subr_entry->called_cv_depth, subr_entry->caller_fid, subr_entry->caller_line, - (long unsigned int)subr_entry->subr_call_seqn); + (long unsigned int)subr_entry->subr_call_seqn, subr_entry); /* only count inclusive time for the outer-most calls */ if (subr_entry->called_cv_depth <= 1) { @@ -2384,13 +2384,15 @@ /* logic based on perl's S_deb_curcv in dump.c */ /* see also http://search.cpan.org/dist/Devel-StackBlech/ */ PERL_CONTEXT *cx; + if (ix < 0) + return Nullcv; if (!si) 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); + logwarn("finding current_cv(%d,%p) - cx_type %d %s, si_type %d\n", + (int)ix, si, CxTYPE(cx), block_type[CxTYPE(cx)], (int)si->si_type); /* the common case of finding the caller on the same stack */ if (CxTYPE(cx) == CXt_SUB || CxTYPE(cx) == CXt_FORMAT) @@ -2411,7 +2413,7 @@ static I32 -subr_entry_setup(pTHX_ COP *prev_cop, subr_entry_t *clone_subr_entry, SV *subr_sv) +subr_entry_setup(pTHX_ COP *prev_cop, subr_entry_t *clone_subr_entry, OPCODE op_type, SV *subr_sv) { int saved_errno = errno; subr_entry_t *subr_entry; @@ -2429,7 +2431,7 @@ if (subr_entry_ix <= prev_subr_entry_ix) { logwarn("NYTProf: stack is confused!\n"); } - Zero(subr_entry, 1, sizeof(subr_entry_t)); + Zero(subr_entry, 1, subr_entry_t); subr_entry->prev_subr_entry_ix = prev_subr_entry_ix; caller_subr_entry = subr_entry_ix_ptr(prev_subr_entry_ix); @@ -2443,10 +2445,15 @@ * 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); + if (op_type == OP_ENTERSUB) { + 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 */ + } } else { subr_entry->called_subnam_sv = newSV(0); /* see incr_sub_inclusive_time */ @@ -2527,14 +2534,14 @@ found_caller_by = "(inherited)"; } - if (trace_level >= 4) - logwarn("Making sub call (%s) at %u:%d from %s::%s %s (seix %d->%d)\n", - SvPV_nolen(subr_sv), + if (trace_level >= 4) { + logwarn("Making sub call at %u:%d from %s::%s %s (seix %d->%d)\n", 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. @@ -2590,18 +2597,18 @@ ) { return run_original_op(op_type); } - if (!profile_stmts) reinit_if_forked(aTHX); if (trace_level >= 99) { - logwarn("entering sub\n"); + logwarn("profiling a call [op %ld]\n", (long)op_type); /* crude, but the only way to deal with the miriad logic at the * start of pp_entersub (which ought to be available as separate sub) */ sv_dump(sub_sv); } + /* Life would be so much simpler if we could reliably tell, at this point, * what sub was going to get called. But we can't in many cases. @@ -2618,7 +2625,7 @@ */ called_cv = NULL; - this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, NULL, sub_sv); + this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, NULL, op_type, sub_sv); /* This call may exit via an exception, in which case the * remaining code below doesn't get executed and the sub call @@ -2669,7 +2676,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, sub_sv); + this_subr_entry_ix = subr_entry_setup(aTHX_ prev_cop, &goto_subr_entry, op_type, sub_sv); } /* push a destructor hook onto the context stack to ensure we account ======================================= --- /trunk/slowops.h Fri Oct 2 14:39:08 2009 +++ /trunk/slowops.h Thu Oct 22 07:42:40 2009 @@ -134,7 +134,7 @@ PL_ppaddr[OP_SSOCKOPT] = pp_slowop_profiler; PL_ppaddr[OP_STAT] = pp_slowop_profiler; PL_ppaddr[OP_SUBST] = pp_slowop_profiler; -PL_ppaddr[OP_SUBSTCONT] = pp_slowop_profiler; +/*PL_ppaddr[OP_SUBSTCONT] = pp_slowop_profiler; XXX needs special handling like OP_GOTO */ PL_ppaddr[OP_SYMLINK] = pp_slowop_profiler; PL_ppaddr[OP_SYSCALL] = pp_slowop_profiler; PL_ppaddr[OP_SYSOPEN] = pp_slowop_profiler; ======================================= --- /trunk/t/22-readstream.t Sun Jul 12 14:55:24 2009 +++ /trunk/t/22-readstream.t Thu Oct 22 07:42:40 2009 @@ -1,11 +1,12 @@ -use Test::More tests => 18; +use Test::More 0.84; use strict; - use lib qw(t/lib); use Config; use NYTProfTest; +plan tests => 18; + use Devel::NYTProf::ReadStream qw(for_chunks); (my $base = __FILE__) =~ s/\.t$//; ======================================= --- /trunk/t/test12.rdt Mon Aug 31 15:04:34 2009 +++ /trunk/t/test12.rdt Thu Oct 22 07:42:40 2009 @@ -16,6 +16,9 @@ fid_block_time 2 1 [ 0 1 ] fid_fileinfo 1 [ test12.p 1 2 0 0 ] fid_fileinfo 1 sub main::BEGIN 0-0 +fid_fileinfo 1 sub main::CORE:dofile 0-0 +fid_fileinfo 1 sub main::RUNTIME 1-1 +fid_fileinfo 1 call 1 main::CORE:dofile [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 2 [ test12.pl 2 2 0 0 ] fid_line_time 1 1 [ 0 1 ] fid_line_time 2 1 [ 0 1 ] @@ -25,3 +28,6 @@ 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:dofile [ 1 0 0 1 0 0 0 0 ] +sub_subinfo main::CORE:dofile called_by 1 1 [ 1 0 0 0 0 0 0 main::RUNTIME ] +sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ] ======================================= --- /trunk/t/test14.rdt Sat Sep 26 15:57:33 2009 +++ /trunk/t/test14.rdt Thu Oct 22 07:42:40 2009 @@ -23,6 +23,7 @@ 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 ] @@ -57,6 +58,8 @@ 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::CORE:require called_by 3 92 [ 2 0 0 0 0 0 0 AutoLoader::AUTOLOAD ] 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/test21-streval3.rdt Thu Aug 6 19:20:50 2009 +++ /trunk/t/test21-streval3.rdt Thu Oct 22 07:42:40 2009 @@ -21,16 +21,20 @@ fid_block_time 1 17 2 4 [ 0 2 ] fid_fileinfo 1 [ test21-streval3.p 1 2 0 0 ] fid_fileinfo 1 sub main::BEGIN 0-0 +fid_fileinfo 1 sub main::CORE:sselect 0-0 fid_fileinfo 1 sub main::RUNTIME 1-1 fid_fileinfo 1 sub main::foo 4-4 fid_fileinfo 1 eval 17 [ 1 2 ] fid_fileinfo 2 [ (eval 0)[test21-streval3.p:17] 1 17 2 2 0 0 ] +fid_fileinfo 2 call 2 main::CORE:sselect [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 2 call 3 main::foo [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 2 eval 4 [ 1 1 ] fid_fileinfo 3 [ (eval 0)[(eval 0)[test21-streval3.p:17]:4] 2 4 3 2 0 0 ] +fid_fileinfo 3 call 2 main::CORE:sselect [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 3 call 3 main::foo [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 3 eval 4 [ 1 0 ] fid_fileinfo 4 [ (eval 0)[(eval 0)[(eval 0)[test21-streval3.p:17]:4]:4] 3 4 4 2 0 0 ] +fid_fileinfo 4 call 2 main::CORE:sselect [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 4 call 3 main::foo [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_line_time 1 4 [ 0 3 ] fid_line_time 1 5 [ 0 1 ] @@ -50,6 +54,10 @@ 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:sselect [ 1 0 0 3 0 0 0 0 ] +sub_subinfo main::CORE:sselect called_by 2 2 [ 1 0 0 0 0 0 0 main::RUNTIME ] +sub_subinfo main::CORE:sselect called_by 3 2 [ 1 0 0 0 0 0 0 main::RUNTIME ] +sub_subinfo main::CORE:sselect called_by 4 2 [ 1 0 0 0 0 0 0 main::RUNTIME ] sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ] sub_subinfo main::foo [ 1 4 4 3 0 0 0 0 ] sub_subinfo main::foo called_by 2 3 [ 1 0 0 0 0 0 0 main::RUNTIME ] ======================================= --- /trunk/t/test30-fork-0.rdt Thu Aug 6 19:20:50 2009 +++ /trunk/t/test30-fork-0.rdt Thu Oct 22 07:42:40 2009 @@ -22,6 +22,7 @@ fid_block_time 1 22 [ 0 1 ] fid_fileinfo 1 [ test30-fork-0.p 1 2 0 0 ] fid_fileinfo 1 sub main::BEGIN 0-0 +fid_fileinfo 1 sub main::CORE:fork 0-0 fid_fileinfo 1 sub main::CORE:print 0-0 fid_fileinfo 1 sub main::CORE:wait 0-0 fid_fileinfo 1 sub main::RUNTIME 1-1 @@ -34,6 +35,7 @@ fid_fileinfo 1 call 11 main::CORE:print [ 1 0 0 0 0 0 0 main::postfork ] fid_fileinfo 1 call 12 main::other [ 1 0 0 0 0 0 0 main::postfork ] fid_fileinfo 1 call 15 main::prefork [ 1 0 0 0 0 0 0 main::RUNTIME ] +fid_fileinfo 1 call 17 main::CORE:fork [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 1 call 19 main::postfork [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_fileinfo 1 call 20 main::other [ 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 ] @@ -59,6 +61,8 @@ 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:fork [ 1 0 0 1 0 0 0 0 ] +sub_subinfo main::CORE:fork called_by 1 17 [ 1 0 0 0 0 0 0 main::RUNTIME ] sub_subinfo main::CORE:print [ 1 0 0 5 0 0 0 0 ] sub_subinfo main::CORE:print called_by 1 2 [ 1 0 0 0 0 0 0 main::prefork ] sub_subinfo main::CORE:print called_by 1 7 [ 3 0 0 0 0 0 0 main::other ] ======================================= --- /trunk/t/test80-recurs.rdt Thu Aug 6 19:20:50 2009 +++ /trunk/t/test80-recurs.rdt Thu Oct 22 07:42:40 2009 @@ -16,8 +16,10 @@ fid_block_time 1 7 [ 0 1 ] fid_fileinfo 1 [ test80-recurs.p 1 2 0 0 ] fid_fileinfo 1 sub main::BEGIN 0-0 +fid_fileinfo 1 sub main::CORE:sselect 0-0 fid_fileinfo 1 sub main::RUNTIME 1-1 fid_fileinfo 1 sub main::recurs 1-5 +fid_fileinfo 1 call 3 main::CORE:sselect [ 3 0 0 0 0 0 0 main::recurs ] fid_fileinfo 1 call 4 main::recurs [ 2 0 0 0 0 0 2 main::recurs ] fid_fileinfo 1 call 7 main::recurs [ 1 0 0 0 0 0 0 main::RUNTIME ] fid_line_time 1 2 [ 0 3 ] @@ -30,6 +32,8 @@ 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:sselect [ 1 0 0 3 0 0 0 0 ] +sub_subinfo main::CORE:sselect called_by 1 3 [ 3 0 0 0 0 0 0 main::recurs ] sub_subinfo main::RUNTIME [ 1 1 1 0 0 0 0 0 ] sub_subinfo main::recurs [ 1 1 5 3 0 0 2 0 ] sub_subinfo main::recurs called_by 1 4 [ 2 0 0 0 0 0 2 main::recurs ] --~--~---------~--~----~------------~-------~--~----~ 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] -~----------~----~----~----~------~----~------~--~---
