Latency test sometimes produces anomalous high latency values

When running the kernel test script, sometimes it hangs without producing output. Sometimes it produces output very slowly. It's still running, though, and when it completes, the last latency value sometimes spike. Also, they sometimes don't match the summary that's produced when the test completes.

This is all done on an Optiplex with in i5. I haven't tried it on other computers.

I've only seen this when running the test at low frequencies (5-20 Hz).

Here is one run 20s run that had a spike at the end.

== Sampling period: 10000 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
RTT|  00:00:01  (periodic user-mode task, 10000 us period, priority 99)
RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat best|--lat worst
RTD|      0.723|      2.302|      3.740|       0|     0|      0.723|      3.740
RTD|      0.363|      2.162|      4.036|       0|     0|      0.363|      4.036
RTD|      0.818|      2.166|      3.377|       0|     0|      0.363|      4.036
RTD|      0.467|      2.114|      3.587|       0|     0|      0.363|      4.036
RTD|      0.173|      1.962|      3.445|       0|     0|      0.173|      4.036
RTD|      0.178|      2.129|      3.787|       0|     0|      0.173|      4.036
RTD|      0.686|      1.961|      3.440|       0|     0|      0.173|      4.036
RTD|      0.425|      1.350|      3.436|       0|     0|      0.173|      4.036
RTD|      0.281|      1.289|      2.807|       0|     0|      0.173|      4.036
RTD|      0.593|      2.131|      3.322|       0|     0|      0.173|      4.036
RTD|      0.853|      2.142|      4.045|       0|     0|      0.173|      4.045
RTD|      0.498|      2.023|      3.381|       0|     0|      0.173|      4.045
RTD|      0.655|      2.312|      5.219|       0|     0|      0.173|      5.219
RTD|      0.898|      2.194|      3.485|       0|     0|      0.173|      5.219
RTD|      0.366|      2.057|      5.694|       0|     0|      0.173|      5.694
RTD|      0.252|      1.843|      3.527|       0|     0|      0.173|      5.694
RTD|      0.597|      2.013|      3.494|       0|     0|      0.173|      5.694
RTD|     -0.124|      0.696|      3.080|       0|     0|     -0.124|      5.694
RTD|     -0.273|      1.206|     14.111|       0|     0|     -0.273|     14.111
---|-----------|-----------|-----------|--------|------|-------------------------
RTS|     -0.273|      1.897|     14.111|       0|     0|    00:00:20/00:00:20

I ran the 20s latency test 6 more times at various RT periods without noticing anything strange. Then,

RTT|  00:00:01  (periodic user-mode task, 200000 us period, priority 99)
RTH|----lat min|----lat avg|----lat max|-overrun|---msw|---lat best|--lat worst
RTD|      1.424|      2.081|      2.765|       0|     0|      1.424|      2.765
RTD|      1.756|      2.905|      4.257|       0|     0|      1.424|      4.257
RTD|      1.682|      2.495|      4.092|       0|     0|      1.424|      4.257
RTD|      1.669|      1.934|      2.172|       0|     0|      1.424|      4.257
RTD|      1.330|      2.503|      3.200|       0|     0|      1.330|      4.257
RTD|      1.369|      3.151|      5.133|       0|     0|      1.330|      5.133
RTD|      2.944|      3.668|      5.016|       0|     0|      1.330|      5.133
RTD|      1.557|      2.086|      2.757|       0|     0|      1.330|      5.133
RTD|      1.568|      2.170|      3.259|       0|     0|      1.330|      5.133
RTD|      1.741|      2.139|      3.365|       0|     0|      1.330|      5.133
RTD|      1.669|      2.311|      3.145|       0|     0|      1.330|      5.133
RTD|      1.423|      2.397|      3.301|       0|     0|      1.330|      5.133
RTD|      1.922|      2.762|      3.413|       0|     0|      1.330|      5.133
RTD|      1.899|      3.125|      3.672|       0|     0|      1.330|      5.133
RTD|      1.307|      2.156|      3.383|       0|     0|      1.307|      5.133
RTD|      1.349|      2.004|      3.222|       0|     0|      1.307|      5.133
RTD|      1.862|      2.466|      3.256|       0|     0|      1.307|      5.133
RTD|      1.774|      2.072|      2.368|       0|     0|      1.307|      5.133
RTD|      1.874|      2.108|      2.269|       0|     0|      1.307|      5.133
---|-----------|-----------|-----------|--------|------|-------------------------
RTS|      1.307|      2.449|      5.133|       0|     0|    00:00:20/00:00:20

This looked fine until I looked at the bottom of the output in test_rt_histdata.txt.

It doesn't match the terminal output. There's a spike to 16.7415 us. I replicated this behaviour in the next run, which I ran for 10 min again at 5 Hz.

I haven't looked through the Xenomai latency test code. Fortunately, I haven't noticed anything like this when running at higher frequencies (10-20 kHz).

Just for note, setting the latency test to very high RT frequencies will also badly mess up the latency test, possibly even make it crash. See below for terminal output:

----->Please enter the frequency (in Hz) that you would like to test, then press enter.
131424
expr: non-integer argument
stress: info: [4776] dispatching hogs: 2 cpu, 0 io, 1 vm, 1 hdd
== Sampling period: 7 us
== Test mode: periodic user-mode task
== All results in microseconds
warming up...
stress: info: [4776] successful run completed in 20s
---|--param|----range-|--samples
---|--param|----range-|--samples
---|--param|----range-|--samples
HSH|--param|--samples-|--average--|---stddev--
HSS|    min|         0|       -nan|      0.000
HSS|    avg|         0|       -nan|      0.000
HSS|    max|         0|       -nan|      0.000

And also a few lines from histdata.txt:

500.303 296352743523
500.303 38654705673
500.305 4613938024961802242
500.305 2310917120274206721
500.307 2341915787780032513
500.308 2540031564293604106
500.308 9012284529577987
500.31 -9223367638774710263
500.31 292733976052008585
500.312 -8789899452505517999
500.312 1
500.313 300647710790
500.315 72
500.315 73

RTXI / rtxi

Latency test sometimes produces anomalous high latency values #60