This is a live mirror of the Perl 5 development currently hosted at https://github.com/perl/perl5
fix make test failures in -Accflags=-DPERL_TRACE_OPS
authorJim Cromie <jim.cromie@gmail.com>
Wed, 20 Jan 2016 23:11:34 +0000 (16:11 -0700)
committerTony Cook <tony@develop-help.com>
Tue, 10 May 2016 01:12:42 +0000 (11:12 +1000)
commite71f25b35412c2e07991432fa6973cc30fbd3701
tree07f89b2f0fdef5455e75f78b0495749c80f4f930
parent83a177d5130b0eaf6e80dc433be6c3ac4ae4fba0
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).
perl.c