From dc3c76a43b488d1a3f673ccac505d74f115c9efb Mon Sep 17 00:00:00 2001
From: Jim Cromie <jim.cromie@gmail.com>
Date: Wed, 20 Jan 2016 16:11:34 -0700
Subject: [PATCH 1/7] 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 | 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
 
 
-- 
2.5.5