In perl.git, the branch blead has been updated <http://perl5.git.perl.org/perl.git/commitdiff/e71f25b35412c2e07991432fa6973cc30fbd3701?hp=83a177d5130b0eaf6e80dc433be6c3ac4ae4fba0>
- Log ----------------------------------------------------------------- commit e71f25b35412c2e07991432fa6973cc30fbd3701 Author: Jim Cromie <[email protected]> Date: Wed Jan 20 16:11:34 2016 -0700 fix make test failures in -Accflags=-DPERL_TRACE_OPS builds with -DPERL_TRACE_OPS currently fail make test, on ~124 files, for both normal & -DDEBUGGING, and plain & threaded configs. These tests fail because they check STDERR content, and reject the extra output issued by perl_destruct() in these builds. It turns out that "Trace of all OPs executed:" by itself is enough to cause the failures. The easiest fix is to silence -DPERL_TRACE_OPS printing by default, and enable it if $ENV{PERL_TRACE_OPS} > 0. Due to various aspects of the design, this is also the best fix. - OP-counting is only done in runops_debug(). runops_standard() avoids all counting overhead, so the only 'cost' then is the extra space in the interpreter structure. - use of runops_debug() vs runops_standard() varies at build, with -DDEBUGGING, and can be changed at runtime, with -MDevel::Peek -e 'BEGIN{runops_debug(0 or 1)}' - when runops_standard is used, perl_destruct() reports ALL-0s OP-exec-counts. This is wrong, silence is better. - when runops_* is toggled, OP-counts will only reflect part of the work done. Given the flexibilty of use, perl_destruct() cannot really know the counts are good, and shouldnt just spew them to STDERR. With this patch, the user asks for the output at runtime. - with patch, the build is not noisy, more usable, no stderr to deal with. miniperl is also silent, reducing `make` output too. - via simple XS, data can be read, cleared, at any compilation phase. with this, data to stderr is just a convienience, not "the way" to get data. Ive got Devel::TraceOps on-deck. I also took the liberty of suppressing "<optype>: 0" prints entirely. - no real info provided (0 count is inferrable by silence) - 0 is usually wrong, unless other OP-counts (from same interp) are non-0 - `make test` on a non-debug threaded build emits 5 million of them And now './perl -e 'print "foo\n"' becomes readably small: foo Trace of all OPs executed: pushmark: 1 gvsv: 1 nextstate: 1 enter: 1 leave: 1 print: 1 NOTES: Since the PERL_TRACE_OPs counting overhead is runtime selectable, it seemed useful to measure and report it: function run_trace_overhead() { for i in seq 1 2; do perf stat -r5 -- ./perl -Ilib -MDevel::Peek -e 'BEGIN{runops_debug(0)}' -e 'for (1..9_999_999){$i++}' perf stat -r5 -- ./perl -Ilib -MDevel::Peek -e 'BEGIN{runops_debug(1)}' -e 'for (1..9_999_999){$i++}' done 2>&1 | grep -E 'Performance|instructions' } bench.pl couldnt do this, not without different --perlargs per contestant. [jimc@popeye perl]$ run_trace_overhead Performance counter stats for './perl -MDevel::Peek -e BEGIN{runops_debug(0)} -e for (1..9_999_999){$i++}' (5 runs): 3,460,280,502 instructions # 1.57 insns per cycle (25.01%) Performance counter stats for './perl -MDevel::Peek -e BEGIN{runops_debug(1)} -e for (1..9_999_999){$i++}' (5 runs): 3,857,253,945 instructions # 2.00 insns per cycle (25.07%) Performance counter stats for './perl -MDevel::Peek -e BEGIN{runops_debug(0)} -e for (1..9_999_999){$i++}' (5 runs): 3,437,504,999 instructions # 1.57 insns per cycle (25.07%) Performance counter stats for './perl -MDevel::Peek -e BEGIN{runops_debug(1)} -e for (1..9_999_999){$i++}' (5 runs): 3,859,640,318 instructions # 2.00 insns per cycle (25.09%) IE: when swapping runops_debug for runops_standard, the instruction count predictably goes up: by 3.8/3.4 = 1.12 in these results. Subject to many caveats, this is a reasonable estimate of the worst-case cost overhead of OP-counting. NB: the insns per cycle above are garbage, on this older 32bit box. but the instruction counts look plausible (I didnt look at the assembly code), and the per-cycle numbers are sane on a 64bit cpu (with a newer PMU). ----------------------------------------------------------------------- Summary of changes: perl.c | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/perl.c b/perl.c index 228a0d8..1d8876b 100644 --- a/perl.c +++ b/perl.c @@ -602,16 +602,25 @@ perl_destruct(pTHXx) my_fflush_all(); #ifdef PERL_TRACE_OPS - /* If we traced all Perl OP usage, report and clean up */ + /* dump OP-counts if $ENV{PERL_TRACE_OPS} > 0 */ + { + const char * const ptoenv = PerlEnv_getenv("PERL_TRACE_OPS"); + UV uv; + + if (!ptoenv || !Perl_grok_atoUV(ptoenv, &uv, NULL) + || !(uv > 0)) + goto no_trace_out; + } PerlIO_printf(Perl_debug_log, "Trace of all OPs executed:\n"); for (i = 0; i <= OP_max; ++i) { - PerlIO_printf(Perl_debug_log, " %s: %"UVuf"\n", PL_op_name[i], PL_op_exec_cnt[i]); - PL_op_exec_cnt[i] = 0; + if (PL_op_exec_cnt[i]) + PerlIO_printf(Perl_debug_log, " %s: %"UVuf"\n", PL_op_name[i], PL_op_exec_cnt[i]); } /* Utility slot for easily doing little tracing experiments in the runloop: */ if (PL_op_exec_cnt[OP_max+1] != 0) PerlIO_printf(Perl_debug_log, " SPECIAL: %"UVuf"\n", PL_op_exec_cnt[OP_max+1]); PerlIO_printf(Perl_debug_log, "\n"); + no_trace_out: #endif -- Perl5 Master Repository
