EFM32: RTC test fails

[amq]

Description of defect

tests-mbed_hal-rtc always fails on some EFM32 targets. Other tests apart of #12371 and #12373 are fine.

It errors out at the RTC - sleep case with:

missing __exit_event_queue event from host test and no result from host test, timeout...

If I comment-out RTC - sleep, the next failing case is RTC - range:

Values Not Within Delta 1 Expected 4 Was 0

Related to 5590f2b and #7009

Target(s) affected by this defect ?

Verified on EFM32PG12_STK3402 and EFM32GG11_STK3701.

EFM32GG_STK3700 is not affected (because it's backed by BURTC instead of RTCC?)

Toolchain(s) (name and version) displaying this defect ?

GNU Tools Arm Embedded 9 2019-q4-major

What version of Mbed-os are you using (tag or sha) ?

master at f73a62afbf4052b4da8c5b862ffb4708a80c1b6e

Also verified with:

mbed-os-5.13.4 at 1bf6b20df9d3cd5f29f001ffc6f0d0fcbbb96118

What version(s) of tools are you using. List all that apply (E.g. mbed-cli)

mbed-cli 1.10.2

How is this defect reproduced ?

mbed test --run -t GCC_ARM -m EFM32PG12_STK3402 -DMBED_EXTENDED_TESTS=1 -n tests-mbed_hal-rtc -v
mbedgt: greentea test automation tool ver. 1.7.4
mbedgt: test specification file '.\BUILD\tests\EFM32PG12_STK3402\GCC_ARM\test_spec.json' (specified with --test-spec option)
mbedgt: using '.\BUILD\tests\EFM32PG12_STK3402\GCC_ARM\test_spec.json' from current directory!
mbedgt: detecting connected mbed-enabled devices...
[1580922380.90][mbedls.lstools_base]No valid file found to update JLink device details
mbedgt: detected 1 device
        | platform_name     | platform_name_unique | serial_port | mount_point | target_id                |
        |-------------------|----------------------|-------------|-------------|--------------------------|
        | EFM32PG12_STK3402 | EFM32PG12_STK3402[0] | COM5        | D:          | 204003F00001DCA9D5A8EF33 |
mbedgt: processing target 'EFM32PG12_STK3402' toolchain 'GCC_ARM' compatible platforms... (note: switch set to --parallel 1)
        | platform_name     | platform_name_unique | serial_port | mount_point | target_id                |
        |-------------------|----------------------|-------------|-------------|--------------------------|
        | EFM32PG12_STK3402 | EFM32PG12_STK3402[0] | COM5:115200 | D:          | 204003F00001DCA9D5A8EF33 |
mbedgt: test case filter (specified with -n option)
        tests-mbed_hal-rtc
        test filtered in 'tests-mbed_hal-rtc'
mbedgt: running 1 test for platform 'EFM32PG12_STK3402' and toolchain 'GCC_ARM'
        use 1 instance of execution threads for testing
mbedgt: checking for 'host_tests' directory above image directory structure
        found 'host_tests' directory in: 'TESTS\host_tests'
mbedgt: selecting test case observer...
        calling mbedhtrun: mbedhtrun -m EFM32PG12_STK3402 -p COM5:115200 -f "BUILD/tests/EFM32PG12_STK3402/GCC_ARM/TESTS/mbed_hal/rtc/rtc.bin" -e "TESTS\host_tests" -d D: -c default -t 204003F00001DCA9D5A8EF33 -r default -C 4 -R 2 --sync 5 -P 60
mbedgt: mbed-host-test-runner: started
[1580922381.75][HTST][INF] host test executor ver. 0.0.12
[1580922381.75][HTST][INF] copy image onto target...
[1580922381.75][COPY][INF] Waiting up to 60 sec for '204003F00001DCA9D5A8EF33' mount point (current is 'D:')...
[1580922381.77][mbedls.lstools_base]No valid file found to update JLink device details
        1 file(s) copied.
[1580922387.87][mbedls.lstools_base]No valid file found to update JLink device details
[1580922388.41][mbedls.lstools_base]No valid file found to update JLink device details
[1580922388.95][mbedls.lstools_base]No valid file found to update JLink device details
[1580922389.46][mbedls.lstools_base]No valid file found to update JLink device details
[1580922389.98][mbedls.lstools_base]No valid file found to update JLink device details
[1580922390.49][HTST][INF] starting host test process...
[1580922390.95][CONN][INF] starting connection process...
[1580922390.95][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1580922390.95][CONN][INF] initializing serial port listener...
[1580922390.95][PLGN][INF] Waiting up to 60 sec for '204003F00001DCA9D5A8EF33' serial port (current is 'COM5')...
[1580922390.95][HTST][INF] setting timeout to: 60 sec
[1580922390.96][mbedls.lstools_base]No valid file found to update JLink device details
[1580922390.97][SERI][INF] serial(port=COM5, baudrate=115200, read_timeout=0.01, write_timeout=5)
[1580922390.97][SERI][INF] reset device using 'default' plugin...
[1580922391.22][SERI][INF] waiting 2.00 sec after reset
[1580922393.22][SERI][INF] wait for it...
[1580922393.22][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1580922393.22][CONN][INF] sending up to 5 __sync packets (specified with --sync=5)
[1580922393.22][CONN][INF] sending preamble 'f155516a-551a-4f98-82e3-e3d1feadfa0a'
[1580922393.31][SERI][TXD] {{__sync;f155516a-551a-4f98-82e3-e3d1feadfa0a}}
[1580922393.33][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1580922393.33][CONN][INF] found SYNC in stream: {{__sync;f155516a-551a-4f98-82e3-e3d1feadfa0a}} it is #0 sent, queued...
[1580922393.33][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1580922393.33][CONN][INF] found KV pair in stream: {{__timeout;60}}, queued...
[1580922393.33][HTST][INF] sync KV found, uuid=f155516a-551a-4f98-82e3-e3d1feadfa0a, timestamp=1580922393.332790
[1580922393.33][HTST][INF] DUT greentea-client version: 1.3.0
[1580922393.34][HTST][INF] setting timeout to: 60 sec
[1580922393.35][CONN][RXD] >>> Running 8 test cases...
[1580922393.35][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
[1580922393.35][CONN][INF] found KV pair in stream: {{__testcase_count;8}}, queued...
[1580922393.35][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - init}}, queued...
[1580922393.35][HTST][INF] host test class: '<class 'mbed_os_tools.test.host_tests.default_auto.DefaultAuto'>'
[1580922393.35][HTST][INF] host test setup() call...
[1580922393.35][HTST][INF] CALLBACKs updated
[1580922393.35][HTST][INF] host test detected: default_auto
[1580922393.36][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - sleep}}, queued...
[1580922393.36][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - persist}}, queued...
[1580922393.36][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - glitch}}, queued...
[1580922393.36][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - range}}, queued...
[1580922393.37][CONN][RXD]
[1580922393.37][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - accuracy}}, queued...
[1580922393.37][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - write/read}}, queued...
[1580922393.37][CONN][INF] found KV pair in stream: {{__testcase_name;RTC - enabled}}, queued...
[1580922393.39][CONN][RXD] >>> Running case #1: 'RTC - init'...
[1580922393.39][CONN][RXD] >>> 'RTC - init': 1 passed, 0 failed
[1580922393.39][CONN][RXD]
[1580922393.39][CONN][RXD] >>> Running case #2: 'RTC - sleep'...
[1580922393.39][CONN][INF] found KV pair in stream: {{__testcase_start;RTC - init}}, queued...
[1580922393.39][CONN][INF] found KV pair in stream: {{__testcase_finish;RTC - init;1;0}}, queued...
[1580922393.39][CONN][INF] found KV pair in stream: {{__testcase_start;RTC - sleep}}, queued...
[1580922453.42][HTST][INF] test suite run finished after 60.08 sec...
[1580922453.43][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1580922453.46][HTST][INF] CONN exited with code: 0
[1580922453.46][HTST][INF] No events in queue
[1580922453.46][HTST][INF] stopped consuming events
[1580922453.46][HTST][INF] host test result(): None
[1580922453.46][HTST][WRN] missing __exit event from DUT
[1580922453.46][HTST][WRN] missing __exit_event_queue event from host test
[1580922453.46][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
[1580922453.46][HTST][INF] calling blocking teardown()
[1580922453.46][HTST][INF] teardown() finished
[1580922453.46][HTST][INF] {{result;timeout}}
mbedgt: retry mbedhtrun 1/1
mbedgt: ['mbedhtrun', '-m', 'EFM32PG12_STK3402', '-p', 'COM5:115200', '-f', '"BUILD/tests/EFM32PG12_STK3402/GCC_ARM/TESTS/mbed_hal/rtc/rtc.bin"', '-e', '"TESTS\\host_tests"', '-d', 'D:', '-c', 'default', '-t', '204003F00001DCA9D5A8EF33', '-r', 'default', '-C', '4', '-R', '2', '--sync', '5', '-P', '60'] failed after 1 count
mbedgt: checking for GCOV data...
mbedgt: mbed-host-test-runner: stopped and returned 'TIMEOUT'
mbedgt: test on hardware with target id: 204003F00001DCA9D5A8EF33
mbedgt: test suite 'tests-mbed_hal-rtc' .............................................................. TIMEOUT in 72.30 sec
        test case: 'RTC - accuracy' .................................................................. SKIPPED in 0.00 sec
        test case: 'RTC - enabled' ................................................................... SKIPPED in 0.00 sec
        test case: 'RTC - glitch' .................................................................... SKIPPED in 0.00 sec
        test case: 'RTC - init' ...................................................................... OK in 0.00 sec
        test case: 'RTC - persist' ................................................................... SKIPPED in 0.00 sec
        test case: 'RTC - range' ..................................................................... SKIPPED in 0.00 sec
        test case: 'RTC - sleep' ..................................................................... ERROR in 0.00 sec
        test case: 'RTC - write/read' ................................................................ SKIPPED in 0.00 sec
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.4549673824
mbedgt: test suite report:
| target                    | platform_name     | test suite         | result  | elapsed_time (sec) | copy_method |
|---------------------------|-------------------|--------------------|---------|--------------------|-------------|
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | TIMEOUT | 72.3               | default     |
mbedgt: test suite results: 1 TIMEOUT
mbedgt: test case report:
| target                    | platform_name     | test suite         | test case        | passed | failed | result  | elapsed_time (sec) |
|---------------------------|-------------------|--------------------|------------------|--------|--------|---------|--------------------|
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - accuracy   | 0      | 0      | SKIPPED | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - enabled    | 0      | 0      | SKIPPED | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - glitch     | 0      | 0      | SKIPPED | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - init       | 1      | 0      | OK      | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - persist    | 0      | 0      | SKIPPED | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - range      | 0      | 0      | SKIPPED | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - sleep      | 0      | 0      | ERROR   | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-rtc | RTC - write/read | 0      | 0      | SKIPPED | 0.0                |
mbedgt: test case results: 6 SKIPPED / 1 OK / 1 ERROR
mbedgt: completed in 72.64 sec
mbedgt: exited with code 1
[mbed] Working path "C:\Users\amq\mbed-os" (program)
[mbed] Exec "mbedgt --test-spec .\BUILD\tests\EFM32PG12_STK3402\GCC_ARM\test_spec.json -n tests-mbed_hal-rtc -V" in "C:\Users\amq\mbed-os"
[mbed] ERROR: "mbedgt" returned error.
       Code: 1
       Path: "C:\Users\amq\mbed-os"
       Command: "mbedgt --test-spec .\BUILD\tests\EFM32PG12_STK3402\GCC_ARM\test_spec.json -n tests-mbed_hal-rtc -V"
---

[ciarmcom]

Internal Jira reference: https://jira.arm.com/browse/MBOTRIAGE-2538

[0xc0170]

cc @ARMmbed/team-silabs

[amq]

Findings so far:

• if RTC - sleep is moved to the end of the suite, then the RTC - range case succeeds (but RTC - sleep still fails)
• if there is wait_ms(1) right after rtc_write() in RTC - sleep, then this case succeeds
• if there is wait_ms(1) right after rtc_write() in RTC - range, then this case succeeds without moving RTC - sleep
• using wait_us(1000) instead of wait_ms(1) doesn't help, a bit counter-intuitively

[amq]

Seems like a context switch is needed.

Also just noticed: #8906, could be related, see also the two fixing PRs.

[amq]

@stevew817 could you have a look?

[stevew817]

I'll see whether I can find something in the implementation that would correlate with your findings. Stay tuned.

[stevew817]

wait_us maps to a busy-wait instead of a thread sleep, so that would explain why there could be a difference between the two.
Also seeing that rtc_write as part of the RTCC implementation is writing to the RTCC directly and to lptick_offset, which could potentially cause an attached lp_ticker event to fire too early or too late. I think the solution may be to add another tracking variable to keep track of the RTC offset, instead of messing with the hardware counter which potentially has a capture/compare already attached.

I need to experiment a bit, but the solution seems within reach.