Bug 5094

Summary: gtod.exp fails on ppc64/i386
Product: systemtap Reporter: Srinivasa DS <srinivasa>
Component: testsuiteAssignee: Unassigned <systemtap>
Status: RESOLVED WORKSFORME    
Severity: normal CC: mhiramat, wcohen
Priority: P2    
Version: unspecified   
Target Milestone: ---   
Host: Target:
Build: Last reconfirmed:

Description Srinivasa DS 2007-10-03 06:27:09 UTC
My environment is Systemtap-20070929 snapshot,elfutils-0.128 and kernel-2.6.23-rc8.
=================================
gtod.exp fails with below message.
==========================================
Running
/home/systemtap/tmp/stap_testing_200710010650/src/testsuite/systemtap.samples/gtod.exp
...
Executing on host: gcc
/home/systemtap/tmp/stap_testing_200710010650/src/testsuite/systemtap.samples/gtod.c
  -lm   -o
/home/systemtap/tmp/stap_testing_200710010650/src/testsuite/systemtap.context/gtod
   (timeout = 300)
1191224898733403 :00 appl^M
1191224898733414 :00 kern^M
..........................

1191224916849431 :98 appl^M
1191224916849434 :98 kern^M
1191224916849438 :98 prog^M
1191224916950432 :99 appl^M
1191224916950434 :99 kern^M
1191224916950438 :99 prog^M
FAIL: gtod (238)
testcase
/home/systemtap/tmp/stap_testing_200710010650/src/testsuite/systemtap.samples/gtod.exp
completed in 27 seconds
===============================
Comment 1 William Cohen 2008-01-15 20:05:49 UTC
I noticed a similar failure on an i686 machine running a stock kernel,
2.6.18-53.1.4EL with the current stap_snap_testing (20080112).  The gtod.exp
test has the following matching:

	-re {^[0-9]+ \:([0-9]+) appl\r\n[0-9]+ \:\1 kern\r\n[0-9]+ \:\1 prog\r\n} {
incr ok; exp_continue }

the \1 before "kern" and "prog" expect need something like the following to match:

1200411986605858 :00 appl

1200411986605862 :00 kern

1200411986605873 :00 prog


However, there are places in the output where the number entries are not grouped
together (notice the 78 before the last 77 and the 79 between the 78's):

1200411986606250 :77 kern
1200411986606252 :77 appl
1200411986606255 :78 kern
1200411986606256 :77 prog
1200411986606257 :78 appl
1200411986606260 :79 kern
1200411986606261 :78 prog
1200411986606262 :79 appl
1200411986606265 :79 prog


It appears that the get_time_of_day is not being monotonic. The particular i686
machine was a laptop, which could have changes in the clock frequency. I wonder
if the hypervisor on the ppc64 could be skewing the results.
Comment 2 Mark Wielaard 2009-04-23 16:44:50 UTC
Seeing something similar on 2.6.27.21-170.2.56.fc10.i686 (SMP)

1240479726271339 :10 appl
1240479726271341 :10 kern
1240479726271347 :10 prog
1240479726281401 :11 appl
1240479726281403 :11 kern
1240479726281409 :11 prog
1240479726291442 :12 kern
1240479726291494 :12 appl
1240479726291501 :12 prog
1240479726301442 :13 kern
1240479726301586 :13 appl
1240479726301594 :13 prog
1240479726311442 :14 kern
1240479726311678 :14 appl
1240479726311686 :14 prog

Notice how the sequence is not always appl-kern-prog, sometimes it is
kern-appl-prog.
Comment 3 William Cohen 2019-05-28 19:50:37 UTC
Seeing the gtod.exp test passing on both ppc64le fc28.

[wcohen@rh-power-vm07 systemtap]$ uname -r
5.0.16-100.fc28.ppc64le
[wcohen@rh-power-vm07 systemtap]$ grep gtod testsuite/systemtap.sum
Running /home/wcohen/systemtap_write/systemtap/testsuite/systemtap.base/gtod.exp ...
PASS: gtod (short range) (100)
PASS: gtod (10ms interval) (100)
PASS: gtod (100ms interval) (100)

And  and i386 f30:

[wcohen@weci686 testsuite]$ uname -r
5.0.17-300.fc30.i686
[wcohen@weci686 testsuite]$ grep gtod systemtap.sum 
Running /usr/share/systemtap/testsuite/systemtap.base/gtod.exp ...
PASS: gtod (short range) (100)
PASS: gtod (10ms interval) (100)
PASS: gtod (100ms interval) (100)