Timing tests are unstable on the ARM_BEETLE_SOC

[bridadan]

Description

• Type: Bug
• Priority: Minor

---

Bug

Target
ARM_BEETLE_SOC

Toolchain:
ARM (maybe others)
Toolchain version:
5

meed-os sha:
Release candidate 5.5.1

Failure

The test will sometimes halt printing {{tick}} messages. The failure log looks like this:

[1498053971.96][HTST][INF] host test executor ver. 1.1.8
[1498053971.96][HTST][INF] copy image onto target...
[1498053971.96][COPY][INF] Waiting up to 60 sec for '500200001d17283f00000000000000000000000097969902' mount point (current is 'J:')...
        1 file(s) copied.
[1498053980.07][HTST][INF] starting host test process...
[1498053980.40][CONN][INF] starting connection process...
[1498053980.40][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1498053980.40][CONN][INF] initializing serial port listener... 
[1498053980.40][PLGN][INF] Waiting up to 60 sec for '500200001d17283f00000000000000000000000097969902' serial port (current is 'COM8')...
[1498053980.41][HTST][INF] setting timeout to: 60 sec
[1498053981.20][SERI][INF] serial(port=COM8, baudrate=9600, read_timeout=0.01, write_timeout=5)
[1498053981.20][SERI][INF] reset device using 'default' plugin...
[1498053981.45][SERI][INF] waiting 1.00 sec after reset
[1498053982.45][SERI][INF] wait for it...
[1498053982.45][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1498053982.45][CONN][INF] sending up to 2 __sync packets (specified with --sync=2)
[1498053982.45][CONN][INF] sending preamble 'ef3c7a85-c178-49d3-b71a-845f38fad58f'
[1498053982.45][SERI][TXD] {{__sync;ef3c7a85-c178-49d3-b71a-845f38fad58f}}
[1498053982.59][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1498053982.64][CONN][INF] found SYNC in stream: {{__sync;ef3c7a85-c178-49d3-b71a-845f38fad58f}} it is #0 sent, queued...
[1498053982.65][HTST][INF] sync KV found, uuid=ef3c7a85-c178-49d3-b71a-845f38fad58f, timestamp=1498053982.644000
[1498053982.66][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1498053982.66][HTST][INF] DUT greentea-client version: 1.3.0
[1498053982.67][CONN][INF] found KV pair in stream: {{__timeout;45}}, queued...
[1498053982.68][HTST][INF] setting timeout to: 45 sec
[1498053982.71][CONN][INF] found KV pair in stream: {{__host_test_name;timing_drift_auto}}, queued...
[1498053982.72][HTST][INF] host test class: '<class 'timing_drift_auto.TimingDriftTest'>'
[1498053982.72][HTST][INF] host test setup() call...
[1498053982.72][HTST][INF] CALLBACKs updated
[1498053982.72][HTST][INF] host test detected: timing_drift_auto
[1498053982.74][CONN][INF] found KV pair in stream: {{__testcase_count;3}}, queued...
[1498053982.77][CONN][RXD] >>> Running 3 test cases...
[1498053982.81][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: 1x ticker}}, queued...
[1498053982.87][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: 2x tickers}}, queued...
[1498053982.91][CONN][RXD] 
[1498053982.91][CONN][INF] found KV pair in stream: {{__testcase_name;Timers: 2x callbacks}}, queued...
[1498053982.95][CONN][RXD] >>> Running case #1: 'Timers: 1x ticker'...
[1498053982.99][CONN][INF] found KV pair in stream: {{__testcase_start;Timers: 1x ticker}}, queued...
[1498053984.02][CONN][INF] found KV pair in stream: {{tick;0}}, queued...
[1498053984.03][HTST][INF] tick! 1498053984.022000
[1498053985.02][CONN][INF] found KV pair in stream: {{tick;1}}, queued...
[1498053985.03][HTST][INF] tick! 1498053985.019000
[1498053986.02][CONN][INF] found KV pair in stream: {{tick;2}}, queued...
[1498053986.02][HTST][INF] tick! 1498053986.016000
[1498053987.02][CONN][INF] found KV pair in stream: {{tick;3}}, queued...
[1498053987.02][HTST][INF] tick! 1498053987.019000
[1498053988.02][CONN][INF] found KV pair in stream: {{tick;4}}, queued...
[1498053988.03][HTST][INF] tick! 1498053988.021000
[1498053989.02][CONN][INF] found KV pair in stream: {{tick;5}}, queued...
[1498053989.02][HTST][INF] tick! 1498053989.016000
[1498053990.02][CONN][INF] found KV pair in stream: {{tick;6}}, queued...
[1498053990.03][HTST][INF] tick! 1498053990.021000
[1498053991.02][CONN][INF] found KV pair in stream: {{tick;7}}, queued...
[1498053991.03][HTST][INF] tick! 1498053991.016000
[1498053992.02][CONN][INF] found KV pair in stream: {{tick;8}}, queued...
[1498053992.04][HTST][INF] tick! 1498053992.021000
[1498053993.02][CONN][INF] found KV pair in stream: {{tick;9}}, queued...
[1498053993.02][HTST][INF] tick! 1498053993.018000
[1498053994.02][CONN][INF] found KV pair in stream: {{tick;10}}, queued...
[1498053994.03][HTST][INF] tick! 1498053994.015000
[1498053994.06][CONN][INF] found KV pair in stream: {{__testcase_finish;Timers: 1x ticker;1;0}}, queued...
[1498053994.10][CONN][RXD] >>> 'Timers: 1x ticker': 1 passed, 0 failed
[1498053994.10][CONN][RXD] 
[1498053994.15][CONN][RXD] >>> Running case #2: 'Timers: 2x tickers'...
[1498053994.19][CONN][INF] found KV pair in stream: {{__testcase_start;Timers: 2x tickers}}, queued...
[1498053995.21][CONN][INF] found KV pair in stream: {{tick;0}}, queued...
[1498053995.21][HTST][INF] tick! 1498053995.208000
[1498053996.21][CONN][INF] found KV pair in stream: {{tick;1}}, queued...
[1498053996.21][HTST][INF] tick! 1498053996.213000
[1498054027.69][HTST][INF] test suite run finished after 45.01 sec...
[1498054027.70][CONN][INF] received special even '__host_test_finished' value='True', finishing
[1498054027.73][HTST][INF] CONN exited with code: 0
[1498054027.73][HTST][INF] No events in queue
[1498054027.74][HTST][INF] stopped consuming events
[1498054027.74][HTST][INF] host test result(): True
[1498054027.74][HTST][WRN] missing __exit event from DUT
[1498054027.74][HTST][WRN] missing __exit_event_queue event from host test
[1498054027.74][HTST][INF] calling blocking teardown()
[1498054027.74][HTST][INF] teardown() finished
[1498054027.74][HTST][INF] {{result;success}}

Greentea sometimes won't report this as a failure, this is due to a bug in how the host test is written. PR #4599 should help with this.

[0xc0170]

@c1728p9 was able to reproduce it, he will update this with more information

cc @mmorenobarm

[c1728p9]

This occurs on the beetle when the last call to us_ticker_set_interrupt sets the time to a time in the past. This code disables the ticker interrupt by setting the count value to 0 in the timer, when really, the intent is to make it fire immediately. I have also attached ticker_test_log.txt, which is from a build of the ticker test, which prints ****Timer set to 0 event**** whenever this condition is met, showing that this is the cause of the hang.

Finally, I created PR #4628, which adds tests to deterministically catch this failure.

[c1728p9]

CC: @studavekar

[0xc0170]

@mmorenobarm Can you please look at the #4605 (comment) comment? How on beetle we shall trigger pending interrupt? setting 0 seems like an issue here.

[cmonr]

@c1728p9 Did anything else happen with this issue after #4628 was closed?

[c1728p9]

This should have been resolved with #4644 which added interrupt immediately functionality to the tickers. CC @0xc0170

[0xc0170]

Closed as resolved via the referenced PR above