Bug 692445

systemtap.base/deref.exp has identical symptom ('metric' line disappearing)

Ditto for:

systemtap.base/logical_and.exp
systemtap.base/print.exp
systemtap.base/timers.exp
systemtap.base/tri.exp

The metric: line is printed when the test succeeds (the expected output matches).

Could you run be_order.stp by hand to see what output is generated:

stap -v /usr/share/systemtap/testsuite/systemtap.base/be_order.stp

Interesting. If I run it by hand, the output is always this, which seems correct:

# stap -v /usr/share/systemtap/testsuite/systemtap.base/be_order.stp -c 'sleep 0.2'
Pass 1: parsed user script and 76 library script(s) using 31984virt/22104res/2992shr kb, in 180usr/10sys/200real ms.
Pass 2: analyzed script: 14 probe(s), 0 function(s), 0 embed(s), 2 global(s) using 32380virt/22856res/3264shr kb, in 10usr/0sys/6real ms.
Pass 3: translated to C into "/tmp/stap7J3dHM/stap_109681a2f951c606d677db851fddb20c_1667.c" using 32488virt/23188res/3572shr kb, in 0usr/0sys/1real ms.
Pass 4: compiled C into "stap_109681a2f951c606d677db851fddb20c_1667.ko" in 4790usr/780sys/5628real ms.
Pass 5: starting run.
systemtap starting probe
systemtap ending probe
systemtap test success
systemtap test success
Pass 5: run completed in 10usr/20sys/222real ms.

When I run 'make RUNTESTFLAGS=systemtap.base/be_order.exp installcheck', sometimes it PASSes, but more often it FAILs with 1 FAIL. But the only difference in appropriate systemtap.log files is the result, the actual systemtap output is identical (and same to the output of the manually executed command):

--- systemtap.log       2011-04-04 09:12:35.616763220 -0400
+++ systemtap.log.pass  2011-04-04 09:12:31.776773151 -0400
@@ -1,4 +1,4 @@
-Test Run By root on Mon Apr  4 09:12:35 2011
+Test Run By root on Mon Apr  4 09:11:26 2011
 Native configuration is s390x-ibm-linux
 
                === systemtap tests ===
@@ -19,8 +19,8 @@
 Running /usr/share/systemtap/testsuite/systemtap.base/be_order.exp ...
 executing: stap -v /usr/share/systemtap/testsuite/systemtap.base/be_order.stp
 spawn stap -v /usr/share/systemtap/testsuite/systemtap.base/be_order.stp
-Pass 1: parsed user script and 76 library script(s) using 31984virt/22104res/2992shr kb, in 180usr/10sys/199real ms.
-Pass 2: analyzed script: 14 probe(s), 0 function(s), 0 embed(s), 2 global(s) using 32380virt/22856res/3264shr kb, in 10usr/0sys/6real ms.
+Pass 1: parsed user script and 76 library script(s) using 31984virt/22104res/2992shr kb, in 190usr/10sys/196real ms.
+Pass 2: analyzed script: 14 probe(s), 0 function(s), 0 embed(s), 2 global(s) using 32380virt/22856res/3264shr kb, in 0usr/0sys/5real ms.
 Pass 3: using cached /usr/share/systemtap/testsuite/.systemtap-root/cache/10/stap_109681a2f951c606d677db851fddb20c_1667.c
 Pass 4: using cached /usr/share/systemtap/testsuite/.systemtap-root/cache/10/stap_109681a2f951c606d677db851fddb20c_1667.ko
 Pass 5: starting run.
@@ -30,12 +30,12 @@
 systemtap ending probe
 systemtap test success
 systemtap test success
-Pass 5: run completed in 10usr/10sys/272real ms.
-FAIL: systemtap.base/be_order.stp shutdown (eof)
+PASS: systemtap.base/be_order.stp shutdown and output
+Pass 5: run completed in 0usr/10sys/273real ms.
+metric:        systemtap.base/be_order.stp     190     10      196     0       0       5       0       0       0       0       0       0       0       10      273
 testcase /usr/share/systemtap/testsuite/systemtap.base/be_order.exp completed in 0 seconds
 
                === systemtap Summary ===
 
-# of expected passes           2
-# of unexpected failures       1
-runtest completed at Mon Apr  4 09:12:35 2011
+# of expected passes           3
+runtest completed at Mon Apr  4 09:11:26 2011


The output part of systemtap.log, in both PASS and FAIL results:

Pass 5: starting run.^M
systemtap starting probe^M
PASS: systemtap.base/be_order.stp startup
PASS: systemtap.base/be_order.stp load generation
systemtap ending probe^M
systemtap test success^M
systemtap test success^M
Pass 5: run completed in 10usr/30sys/272real ms.^M

And it is really triggered by some change in systemtap, because the old systemtap never ends with FAIL with identical testcase, it always PASSes. The environment and testcase is identical, I only downgrade these three packages to 1.2-11.el6_0.s390x versions:

systemtap
systemtap-runtime
systemtap-sdt-devel

This is all some sort of minor testsuite problem, parsing pseudo-benchmarking 
data out of the stap per-pass message ("Pass 4: .... done in ... ms.").

Development Management has reviewed and declined this request.  You may appeal
this decision by reopening this request.

Fixed upstream in commit 4f29ad2:

<http://sourceware.org/git/gitweb.cgi?p=systemtap.git;a=patch;h=4f29ad20df5481f80e0f0ce0515067a76fd77c1d>

This change modified lib/stap_run.exp, which is a test script used by several testcases.  Regular expressions used by test harness program 'expect' are quite tricky (and sometimes seem to succeed and fail based on timing).

I ran the testsuite before and after this change, and I got 15 additional passes after this change (and no failure regressions).  Here is a list of testcases that had additional passes after this change:

systemtap.base/alias-condition.exp
systemtap.base/array_size.exp
systemtap.base/be_order.exp
systemtap.base/deref.exp
systemtap.base/global_init.exp
systemtap.base/global_vars.exp
systemtap.base/if.exp
systemtap.base/inc.exp
systemtap.base/kretprobe-vars.exp
systemtap.base/not.exp
systemtap.base/optim_voidstmt.exp
systemtap.base/print.exp

Could comment 9 patch be added to 6.1 version too? Flakey testcases means more investigation work.

    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
Cause
    The pattern matching in stap_run.exp was too picky at times.
Consequence
    Some of the tests would fail the pattern matching and be reported
    as failures even when the tests were actually successfully run.
Fix
    The end-of-line matching ('$') was removed from the pattern matching.
Result
    The tests that were sometime reporting failures on s390x 
    such as systemtap.base/be_order.stp should reliably pass now.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2011-1517.html