EFM32: sleep manager test fails

[amq]

Description of defect

tests-mbed_hal-sleep_manager almost always fails on EFM32. Other tests apart of #12371 are fine.

It errors out at the sleep_auto case with:

Values Not Within Delta 2000 Expected 19989 Was 59310. Deep sleep mode locked, but still used

If I comment-out the sleep_auto case, then the suite succeeds.

Related to #7582

Target(s) affected by this defect ?

Verified on EFM32GG_STK3700, EFM32PG12_STK3402 and EFM32GG11_STK3701, most probably affects all EFM32 targets.

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-sleep_manager -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...
[1580919086.52][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-sleep_manager
        test filtered in 'tests-mbed_hal-sleep_manager'
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/sleep_manager/sleep_manager.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
[1580919087.36][HTST][INF] host test executor ver. 0.0.12
[1580919087.36][HTST][INF] copy image onto target...
[1580919087.36][COPY][INF] Waiting up to 60 sec for '204003F00001DCA9D5A8EF33' mount point (current is 'D:')...
[1580919087.38][mbedls.lstools_base]No valid file found to update JLink device details
        1 file(s) copied.
[1580919093.49][mbedls.lstools_base]No valid file found to update JLink device details
[1580919094.03][mbedls.lstools_base]No valid file found to update JLink device details
[1580919094.57][mbedls.lstools_base]No valid file found to update JLink device details
[1580919095.11][mbedls.lstools_base]No valid file found to update JLink device details
[1580919095.64][mbedls.lstools_base]No valid file found to update JLink device details
[1580919096.16][HTST][INF] starting host test process...
[1580919096.61][CONN][INF] starting connection process...
[1580919096.62][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1580919096.62][CONN][INF] initializing serial port listener...
[1580919096.62][PLGN][INF] Waiting up to 60 sec for '204003F00001DCA9D5A8EF33' serial port (current is 'COM5')...
[1580919096.62][HTST][INF] setting timeout to: 60 sec
[1580919096.63][mbedls.lstools_base]No valid file found to update JLink device details
[1580919096.63][SERI][INF] serial(port=COM5, baudrate=115200, read_timeout=0.01, write_timeout=5)
[1580919096.63][SERI][INF] reset device using 'default' plugin...
[1580919096.88][SERI][INF] waiting 2.00 sec after reset
[1580919098.89][SERI][INF] wait for it...
[1580919098.89][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1580919098.89][CONN][INF] sending up to 5 __sync packets (specified with --sync=5)
[1580919098.89][CONN][INF] sending preamble 'b7612ceb-0d97-46a0-8ccf-df5b09f77217'
[1580919098.91][SERI][TXD] {{__sync;b7612ceb-0d97-46a0-8ccf-df5b09f77217}}
[1580919098.93][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1580919098.93][CONN][INF] found SYNC in stream: {{__sync;b7612ceb-0d97-46a0-8ccf-df5b09f77217}} it is #0 sent, queued...
[1580919098.93][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1580919098.93][CONN][INF] found KV pair in stream: {{__timeout;15}}, queued...
[1580919098.93][HTST][INF] sync KV found, uuid=b7612ceb-0d97-46a0-8ccf-df5b09f77217, timestamp=1580919098.931561
[1580919098.93][HTST][INF] DUT greentea-client version: 1.3.0
[1580919098.93][HTST][INF] setting timeout to: 15 sec
[1580919098.94][CONN][RXD] >>> Running 4 test cases...
[1580919098.94][CONN][INF] found KV pair in stream: {{__host_test_name;default_auto}}, queued...
[1580919098.94][CONN][INF] found KV pair in stream: {{__testcase_count;4}}, queued...
[1580919098.94][CONN][INF] found KV pair in stream: {{__testcase_name;deep sleep lock/unlock}}, queued...
[1580919098.94][HTST][INF] host test class: '<class 'mbed_os_tools.test.host_tests.default_auto.DefaultAuto'>'
[1580919098.94][HTST][INF] host test setup() call...
[1580919098.95][HTST][INF] CALLBACKs updated
[1580919098.95][HTST][INF] host test detected: default_auto
[1580919098.96][CONN][INF] found KV pair in stream: {{__testcase_name;deep sleep locked USHRT_MAX times}}, queued...
[1580919098.96][CONN][INF] found KV pair in stream: {{__testcase_name;sleep_auto calls sleep/deep sleep based on lock}}, queued...
[1580919098.97][CONN][RXD]
[1580919098.97][CONN][RXD] >>> Running case #1: 'deep sleep lock/unlock'...
[1580919098.97][CONN][INF] found KV pair in stream: {{__testcase_name;deep sleep lock/unlock test_check}}, queued...
[1580919098.99][CONN][RXD] >>> 'deep sleep lock/unlock': 1 passed, 0 failed
[1580919098.99][CONN][RXD]
[1580919098.99][CONN][INF] found KV pair in stream: {{__testcase_start;deep sleep lock/unlock}}, queued...
[1580919098.99][CONN][INF] found KV pair in stream: {{__testcase_finish;deep sleep lock/unlock;1;0}}, queued...
[1580919099.00][CONN][RXD] >>> Running case #2: 'deep sleep locked USHRT_MAX times'...
[1580919099.00][CONN][INF] found KV pair in stream: {{__testcase_start;deep sleep locked USHRT_MAX times}}, queued...
[1580919099.18][CONN][RXD] >>> 'deep sleep locked USHRT_MAX times': 1 passed, 0 failed
[1580919099.18][CONN][RXD]
[1580919099.18][CONN][INF] found KV pair in stream: {{__testcase_finish;deep sleep locked USHRT_MAX times;1;0}}, queued...
[1580919099.20][CONN][RXD] >>> Running case #3: 'sleep_auto calls sleep/deep sleep based on lock'...
[1580919099.21][CONN][INF] found KV pair in stream: {{__testcase_start;sleep_auto calls sleep/deep sleep based on lock}}, queued...
mbedgt: :172::FAIL: Values Not Within Delta 2000 Expected 19989 Was 59310. Deep sleep mode locked, but still used
[1580919099.24][CONN][RXD] :172::FAIL: Values Not Within Delta 2000 Expected 19989 Was 59310. Deep sleep mode locked, but still used
[1580919099.25][CONN][INF] found KV pair in stream: {{__testcase_finish;sleep_auto calls sleep/deep sleep based on lock;0;1}}, queued...
[1580919099.26][CONN][RXD] >>> 'sleep_auto calls sleep/deep sleep based on lock': 0 passed, 1 failed with reason 'Assertion Failed'
[1580919099.26][CONN][RXD]
[1580919099.26][CONN][RXD] >>> Test cases: 2 passed, 1 failed with reason 'Assertion Failed'
[1580919099.26][CONN][RXD] >>> TESTS FAILED!
[1580919099.27][CONN][INF] found KV pair in stream: {{__testcase_summary;2;1}}, queued...
[1580919099.27][CONN][INF] found KV pair in stream: {{end;failure}}, queued...
[1580919099.27][CONN][INF] found KV pair in stream: {{__exit;0}}, queued...
[1580919099.27][HTST][INF] __exit(0)
[1580919099.27][HTST][INF] __notify_complete(False)
[1580919099.27][HTST][INF] __exit_event_queue received
[1580919099.27][HTST][INF] test suite run finished after 0.34 sec...
[1580919099.28][CONN][INF] received special event '__host_test_finished' value='True', finishing
[1580919099.31][HTST][INF] CONN exited with code: 0
[1580919099.31][HTST][INF] Some events in queue
[1580919099.31][HTST][INF] stopped consuming events
[1580919099.31][HTST][INF] host test result() call skipped, received: False
[1580919099.31][HTST][INF] calling blocking teardown()
[1580919099.31][HTST][INF] teardown() finished
[1580919099.31][HTST][INF] {{result;failure}}
mbedgt: retry mbedhtrun 1/1
mbedgt: ['mbedhtrun', '-m', 'EFM32PG12_STK3402', '-p', 'COM5:115200', '-f', '"BUILD/tests/EFM32PG12_STK3402/GCC_ARM/TESTS/mbed_hal/sleep_manager/sleep_manager.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 'FAIL'
mbedgt: test on hardware with target id: 204003F00001DCA9D5A8EF33
mbedgt: test suite 'tests-mbed_hal-sleep_manager' .................................................... FAIL in 12.51 sec
        test case: 'deep sleep lock/unlock' .......................................................... OK in 0.00 sec
        test case: 'deep sleep lock/unlock test_check' ............................................... SKIPPED in 0.00 sec
        test case: 'deep sleep locked USHRT_MAX times' ............................................... OK in 0.18 sec
        test case: 'sleep_auto calls sleep/deep sleep based on lock' ................................. FAIL in 0.04 sec
mbedgt: test case summary: 2 passes, 1 failure
mbedgt: utest test case summary mismatch: utest reported passes and failures miscount!
        reported by utest: passes = 2, failures 1)
        test case result count: passes = 2, failures 2)
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.7515933090
mbedgt: test suite report:
| target                    | platform_name     | test suite                   | result | elapsed_time (sec) | copy_method |
|---------------------------|-------------------|------------------------------|--------|--------------------|-------------|
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-sleep_manager | FAIL   | 12.51              | default     |
mbedgt: test suite results: 1 FAIL
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-sleep_manager | deep sleep lock/unlock                          | 1      | 0      | OK      | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-sleep_manager | deep sleep lock/unlock test_check               | 0      | 0      | SKIPPED | 0.0                |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-sleep_manager | deep sleep locked USHRT_MAX times               | 1      | 0      | OK      | 0.18               |
| EFM32PG12_STK3402-GCC_ARM | EFM32PG12_STK3402 | tests-mbed_hal-sleep_manager | sleep_auto calls sleep/deep sleep based on lock | 0      | 1      | FAIL    | 0.04               |
mbedgt: test case results: 2 OK / 1 SKIPPED / 1 FAIL
mbedgt: completed in 12.87 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-sleep_manager -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-sleep_manager -V"
---

[ciarmcom]

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

[0xc0170]

cc @ARMmbed/team-silabs @fkjagodzinski

[stevew817]

@amq this test seems to be failing due to test methodology in combination with the hardware in use. us_ticker on Silicon Labs targets exposes a 16-bit timer, running at a frequency that gives at least microsecond resolution (>1MHz).
I've tested this specifically on GG11 STK, where the core frequency is 50MHz, and the timer backing the us_ticker is running at 3.125 MHz. This is information reported through the ticker_info struct. What happens is that the statically-configured sleep period (20ms) in the sleep manager test is barely larger than the ticker period (16 bits @ 3.125MHz = 20.97ms), and the sleep manager test doesn't track overflows on the us ticker. Since the allowed mismatch is 10%, the tests expect a us_ticker difference of between 18 and 22 ms. 22 ms > 20.97, meaning this test needs to be changed in order to support this constellation of hardware.

If I change the sleep time to 10ms instead of 20, the test passes. @fkjagodzinski, is it you who is responsible for maintaining this test?

[fkjagodzinski]

Yes, @stevew817 I'm the author of this test. @mprse could you look into this?

[mprse]

I'll check this today.

[mprse]

The fix can be found here PR #12519. Please review.

@stevew817 Just a small clarification for your analysis.

the sleep manager test doesn't track overflows on the us ticker

Actually the test handles wraparound on the us ticker:

mbed-os/TESTS/mbed_hal/sleep_manager/main.cpp

Line 199 in 5969fdf

us_diff2 = (us_ts1 <= us_ts2) ? (us_ts2 - us_ts1) : (us_ticker_mask - us_ts1 + us_ts2 + 1);

The problem is that while handling wraparound we have mixed types of values. Timestamps are already converted to us and us_ticker_mask is the max ticker count in ticks. More details can be found in the PR description.

[stevew817]

@0xc0170 this issue can be closed since #12519 was merged.