fix variable interpolation into single-quoted string

commit b38b314560a4ad7d467edc3c24c3895b70b9e1a6 changed hardcoded
test-number to an interpolated var, but left the single-quoting,
resulting in a bare ok.  The test harnesses tolerate that, but I doubt
it was intended.
t/TEST: add -w to shebang, fix one warning

Adding -w should be ok, despite peculiar code style; it avoids
require, unlike use strict etc.  Added risk of perl brokenness is
vanishingly small.  Also fix one used-once warning, and one spelling
error.
t/TEST: move our @found out to its real scope

move declaration of our @found outside of the function,
use strict doesnt like it declared inside.

  $ perl -cw -Ilib -Mstrict t/TEST
  Variable "@found" is not imported at t/TEST line 198.
  Variable "@found" is not imported at t/TEST line 202.
  Global symbol "@found" requires explicit package name at t/TEST line 198.
  Global symbol "@found" requires explicit package name at t/TEST line 202.
t/TEST: add a common timestamp

Add a tstamp var, filled like "2012-1019-1614-18-$$", with TEST start
time and pid.  Any reports files written with this in the name are
then unique and ordered, and corelatable with other reports (say from
sar, iostat, etc).  Timestamping with start time allows users to see
runtime after the fact by comparing the filename to the filesystem
timestamp.
t/TEST: rename $options to $opts to shorten long lines
t/TEST: comment some of the <$results> loop vars

Add comments to var declarations, as 1st step to rewrite for clarity.
t/TEST: $failure doesnt need to use defined

$failure handling in <$results> processing loop does not need extra
subtlety of defined-ness checks - just give it an initial (false)
value, and check for truth.
t/TEST: add -perfstat option to run tests under linux perf stat

Add a simple way to run each test-script under linux perf stat, via a
-perfstat(=<stuff>)? cmdline option.  To make the option available for
make test and make test_harness, add TEST_OPTS envar, prepend it to
@ARGV, and move early return 1 if $::do_nothing (for subroutine reuse
via require) below cmdline option processing.

With this:

    export TEST_OPTS=-perfstat
    make test

writes a single file, like "t/perf.2012-1020-0848-52-5614" containing
perf reports for each test, each like this:

 Performance counter stats for './perl base/cond.t':

          3.155154 task-clock                #    0.807 CPUs utilized
                 2 context-switches          #    0.634 K/sec
                 1 CPU-migrations            #    0.317 K/sec
               464 page-faults               #    0.147 M/sec
         4,558,961 cycles                    #    1.445 GHz
   <not supported> stalled-cycles-frontend
   <not supported> stalled-cycles-backend
         3,904,114 instructions              #    0.86  insns per cycle         [ 9.00%]
     <not counted> branches
     <not counted> branch-misses

       0.003909833 seconds time elapsed

The perf-reports have lots of info, and it takes very little
extra CPU to run:
				export TEST_OPTS=-perfstat
	time make test		time make test
	--------------		--------------
	real	25m41.122s	real	26m30.719s
	user	18m28.773s	user	18m43.286s
	sys	1m12.705s	sys	1m33.398s

When -perfstat=M is passed, "perf stat --repeat M -- perl test-script"
runs the script M times, and computes standard deviation of each
measurement.  This provides a noise-floor when evaluating the
performance impacts of a change, and demonstrates the limited
suitability of each test-script for use in performance assessment.

 Performance counter stats for './perl -I.. -MTestInit=U1 ../lib/Time/localtime.t' (4 runs):

         59.247079 task-clock                #    0.971 CPUs utilized            ( +-  3.19% )
                14 context-switches          #    0.228 K/sec                    ( +- 13.01% )
                22 CPU-migrations            #    0.367 K/sec                    ( +- 13.05% )
             1,526 page-faults               #    0.026 M/sec
       148,891,976 cycles                    #    2.513 GHz                      ( +-  1.29% ) [49.76%]
        59,864,155 stalled-cycles-frontend   #   40.21% frontend cycles idle     ( +-  2.02% ) [50.16%]
        32,113,905 stalled-cycles-backend    #   21.57% backend  cycles idle     ( +-  2.80% ) [51.17%]
       110,419,248 instructions              #    0.74  insns per cycle
                                             #    0.54  stalled cycles per insn  ( +-  0.69% ) [51.63%]
        24,597,068 branches                  #  415.161 M/sec                    ( +-  1.61% ) [51.04%]
         1,487,542 branch-misses             #    6.05% of all branches          ( +-  1.67% ) [50.45%]

       0.061010337 seconds time elapsed                                          ( +-  3.37% )

export TEST_OPTS="-perfstat=reps=4:rptdir=~/perl/perf:name=newname:tool=perf stat"

This envar value overrides the command wrapper defaults to set repeat
count (so that perf stat computes stddev of its measurements),
report-dir (to a separate data-repo thats not killed by git clean
-dxf), and file-name (to convey branch-name and/or config-info; a
timestamp is appended for uniqueness), and the tool and tool options
to run under.

The command wrapper is semi-generic, but not sufficiently so to fully
support running under valgrind, cachegrind etc; the --repeat M will
probably choke other tools.  This is readily fixable, but there are
other issues; valgrind post-processing is the biggest.
t/TEST: make test loop work for perf stat --repeat 3

Make <$results> processing loop accept repeated output from
test-script if run as "perf stat --repeat X -- test-script".

This boils down to tweaking leader (1..N) handling, by disarming
if ($seen_ok) ... check, allowing "ok N" in X passes after 1st.

TBD - further tweaks needed, get 2 dozen failures now on make test
t/TEST: simplify <$results> processing loop

Old loop is complicated for what it does, and has lots of state vars
which are updated midway thru loop, and affect choices both in that
iteration and in subsequent ones.  Do wholesale replacement (old code
is already using hashes, so theyre fair game)

Change details include (tb merged into previous):
- drop $failure, use @fails (accumulate failures)
- move all err checks together (above Valgrind handling)
- some corrections to err tests
- comment out now unused vars

new loop now works, with:
 TEST_OPTS=-perfstat=rptdir=/home/jimc/projects/perl-core/perf
 HARNESS_TIMER=/home/jimc/projects/perl-core/timings

t/re/pat_advanced ............................................. ok     2578 ms  1690 ms   180 ms
t/TEST: tolerate bare ok, or extra spaces between ok and N

- tolerate bare ok
- allow extra spaces after ok, not just single space
print times() in TestInit END, read them in t/TEST

Currently, t/TEST calls times() before and after each testfile, and
computes elapsed times, child user and system times.  This has several
drawbacks:

- the self user/system times are for t/TEST and are uninteresting

- the child times are aggregated for all children which may be forked
  by the testfile, and we lose possibly interesting info wrt split of
  cpu usage between the testfile and its children.

- parallel testing (ala HARNESS_OPTIONS=j4 make test_harness) will
  corrupt data (the real problem).  The child user/system numbers
  taken by t/TEST will be for whatever harness is running
  concurrently.

Fix this by calling times() in TestInit.pm, from END block, and print
the values as a diagnostic output line (# ET: ...), and collect them
in t/TEST.  This also has some (minor) drawbacks:

- Tests in t/{base,comp,run} dont use TestInit, and thus dont emit
  this timing info.  We can forgo these; we get # ET numbers on the
  rest, and still have the timings done by t/TEST itself for all test
  files.

- "# ET: .." is something of a misnomer, they are not "elapsed times",
  but are cpu-usage times given to the process, and are largely stable
  under various system loads.  That said, "ET" has enough mnemonic
  value that I chose to leave it.

- TestInit: END{} block must untie a tied STDOUT to avoid failures,
  which foregos this output from a small number of tests.  The END{}
  will execute in all perl children (see below) which provides more
  data, but can be confusing, and the order which they happen depends
  upon the test specifics.

To minimize disruption of existing harnesses/parsing, printing of
additional timing data depends on HARNESS_TIMER value.

HARNESS_TIMER=1 make test;
t/io/nargv ................ ok       18 ms

HARNESS_TIMER=2 make test;
t/comp/colon .............. ok       17 ms    10 ms     0 ms
t/comp/decl ............... ok        4 ms     0 ms     0 ms
t/comp/final_line_num ..... ok        5 ms     0 ms    10 ms
t/comp/fold ............... ok       10 ms    10 ms     0 ms
t/comp/form_scope ......... ok        8 ms     0 ms    10 ms

HARNESS_TIMER=3 make test;
HARNESS_TIMER=~/perl/perf make test; # (existing directory)
(with tests that have non-zero times from TestInit)
t/re/pat_advanced_thr ..... ok      324 ms   270 ms    40 ms	# ET: (ms) u:240 s:20 cu:0 cs:10
t/re/pat_psycho ........... ok     7596 ms  7510 ms    40 ms	# ET: (ms) u:6630 s:10 cu:840 cs:10
t/re/pat_psycho_thr ....... ok     7691 ms  7580 ms    60 ms	# ET: (ms) u:6720 s:30 cu:840 cs:20

As in a previous patch, if HARNESS_TIMER names an existing directory,
all timing data is written to a Storable file in that directory,
allowing them to be compared against each other later.

    '../cpan/Archive-Tar/t/02_methods.t' => [
      '766.416788101196',
      '460.000000000001',
      '290.000000000001',
      '# ET: (ms) u:440 s:130 cu:10 cs:150 '
    ],
    ...

Again, note the sometimes large discrepancies in the times collected.
Its typical that the t/TEST and TestInit numbers will differ by at
least 10 ms (the timing quantization), and this applies to each of the
6 numbers collected (2, 4) from respective times() callsites.

Note also the many reporting children in the getppid test.

t/op/glob ........... ok       68 ms    40 ms    20 ms	# ET: (ms) u:30 s:0 cu:0 cs:0
t/op/gmagic ......... ok       16 ms    10 ms     0 ms	# ET: (ms) u:0 s:0 cu:0 cs:0
t/op/goto ........... ok      115 ms    60 ms    60 ms	# ET: (ms) u:20 s:10 cu:20 cs:30

t/op/getppid ........ ok     4022 ms    20 ms     0 ms	# ET: (ms) u:0 s:0 cu:0 cs:0
  # ET: (ms) u:0 s:0 cu:0 cs:0 # ET: (ms) u:0 s:0 cu:0 cs:0 # ET: (ms) u:0 s:0 cu:0 cs:0
  # ET: (ms) u:10 s:0 cu:0 cs:0

t/porting/podcheck .. ok    14983 ms 14560 ms   200 ms	# ET: (ms) u:14510 s:190 cu:0 cs:0
t/porting/regen ..... ok     1034 ms   890 ms   120 ms	# ET: (ms) u:20 s:10 cu:860 cs:100
fixup op/magic.t under HARNESS_TIMER=1 make test

Hack t/op/magic.t parent process to strip the trailing "# ET: ... "
added to child's output, since this fouls the parent's parsing,
causing the test to fail.
t/TEST: add more info to Storable file written for HARNESS_TIMER=<directory>

Add several fingerprint items to Storable file:

smolt_id: which ties to a public machine profile database, to support
comparisons of similar machines.  This ID is not the same as the
public profile, but its a start.  A python file suggests that pub-uuid
exists, but I dont have it.

config_cksum: md5 of config.sh, after filtering date-ish lines and comments.

Data changes:

Add PID to ' # ET: timing-data ' line printed by TestInit.pm END block
in each test-file that uses it (usually by t/TEST adding -MTestInit to
the test invocation).  In t/TEST, instead of saving timing-data as a
string, parse it into an array of hashes, and add it to the timing
data saved to the storable file.

The array preserves the order of END/exit of all the perl subtasks (a
handful of tests are multi-process, notably: getppid, io_sock,
io_unix), which should be deterministic, and thus comparable across
runs by their array index.  PIDs of each sub-task are saved in the
hashes, and may be useful for matching with other pid-bearing data
sampled during the run, but they mildly complicate the comparison of
timing data across multiple runs.  Gaps in the sub-task pids also
indicate the process forking load of the system.