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 ===============================
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.
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.
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)