tests/kernel/timer/timer_behavior/kernel.timer.timer fails at nrf54h20dk@0.9.0/nrf54h20/cpurad

[nordic-piks]

Describe the bug
The tests/kernel/timer/timer_behavior/kernel.timer.timer fails

Observed for:

• nrf54h20dk@0.9.0/nrf54h20/cpurad

To Reproduce
Steps to reproduce the behavior:

1. have nrf54h20dk@0.9.0/nrf54h20/cpurad connected
2. go to your zephyr dir
3. call ./scripts/twister -T tests/kernel/timer/timer_behavior -p nrf54h20dk@0.9.0/nrf54h20/cpurad --device-testing --device-serial /dev/ttyACM1 -v --inline-logs
4. See console output with error

Expected behavior
Valid console output

Impact
Not clear

Logs and console output

*** Booting Zephyr OS build v4.1.0-2271-g68b2e7d677cc ***
Running TESTSUITE timer_jitter_drift
===================================================================
START - test_jitter_drift_timer_period
periodic timer behavior test using built-in restart mechanism
collecting time samples for approx 10 seconds
periodic timer samples gathered, calculating statistics
timer clock rate 1000000, kernel tick rate 31250
expected period drift: 24 us
period duration statistics for 10000 samples (0 rollovers):
  expected: 1000 us,       1000.000000 cycles
  min:      992.000000 us, 992 cycles
  max:      1047.000000 us, 1047 cycles
  mean:     1024.001700 us, 1024.001700 cycles
  variance: 543.967697 us, 543.967697 cycles
  stddev:   23.323115 us, 23.323115 cycles
timer start cycle 291982, end cycle 10531999,
total time 10240017.000000 us, expected time 10000000.000000 us,
expected time drift 240000.000000 us, difference 17.000000 us
RECORD: {"testcase":"jitter_drift_timer", "mechanism":"builtin", "stats_count":10000, "rollovers":0, "mean_us":1024.001700, "mean_cycles":1024, "stddev_us":23.323115, "stddev_cycles":23, "var_us":543.967697, "var_cycles":544, "min_us":992.000000, "min_cycles":992, "max_us":1047.000000, "max_cycles":1047, "timer_start_cycle": 291982, "timer_end_cycle": 10531999, "total_time_us":10240017.000000, "expected_total_time_us":10000000.000000, "expected_total_drift_us":240000.000000, "total_drift_us":17.000000, "expected_period_cycles":1000, "expected_period_drift_us":24.000000, "sys_clock_hw_cycles_per_sec":1000000, "CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC":1000000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":31250, "CONFIG_TIMER_TEST_PERIOD":1000, "CONFIG_TIMER_TEST_SAMPLES":10000, "MAX_STD_DEV":10}

    Assertion failed at ../../../../../../../../../zephyr/tests/kernel/timer/timer_behavior/src/jitter_drift.c:334: do_test_using: (stddev_us < (double)max_stddev is false)
Standard deviation (in microseconds) outside expected bound
 FAIL - test_jitter_drift_timer_period in 10.430 seconds
===================================================================
START - test_jitter_drift_timer_startdelay
periodic timer behavior test using explicit start with delay
collecting time samples for approx 10 seconds
periodic timer samples gathered, calculating statistics
timer clock rate 1000000, kernel tick rate 31250
expected period drift: 24 us
period duration statistics for 10000 samples (0 rollovers):
  expected: 1000 us,       1000.000000 cycles
  min:      992.000000 us, 992 cycles
  max:      1042.000000 us, 1042 cycles
  mean:     1024.001700 us, 1024.001700 cycles
  variance: 514.644097 us, 514.644097 cycles
  stddev:   22.685769 us, 22.685769 cycles
timer start cycle 10736232, end cycle 20976249,
total time 10240017.000000 us, expected time 10000000.000000 us,
expected time drift 240000.000000 us, difference 17.000000 us
RECORD: {"testcase":"jitter_drift_timer", "mechanism":"startdelay", "stats_count":10000, "rollovers":0, "mean_us":1024.001700, "mean_cycles":1024, "stddev_us":22.685769, "stddev_cycles":23, "var_us":514.644097, "var_cycles":515, "min_us":992.000000, "min_cycles":992, "max_us":1042.000000, "max_cycles":1042, "timer_start_cycle": 10736232, "timer_end_cycle": 20976249, "total_time_us":10240017.000000, "expected_total_time_us":10000000.000000, "expected_total_drift_us":240000.000000, "total_drift_us":17.000000, "expected_period_cycles":1000, "expected_period_drift_us":24.000000, "sys_clock_hw_cycles_per_sec":1000000, "CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC":1000000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":31250, "CONFIG_TIMER_TEST_PERIOD":1000, "CONFIG_TIMER_TEST_SAMPLES":10000, "MAX_STD_DEV":10}

    Assertion failed at ../../../../../../../../../zephyr/tests/kernel/timer/timer_behavior/src/jitter_drift.c:334: do_test_using: (stddev_us < (double)max_stddev is false)
Standard deviation (in microseconds) outside expected bound
 FAIL - test_jitter_drift_timer_startdelay in 10.430 seconds
===================================================================
TESTSUITE timer_jitter_drift failed.
Running TESTSUITE timer_tick_train
===================================================================
START - test_one_tick_timer_train
Initializing 4 Timers, Tick Rate 31250Hz, Expecting 78125 callbacks in 11000 ms
Starting Timers with Skews
Faking busy work, remaining timers is 4, timer callbacks 1
Faking busy work, remaining timers is 4, timer callbacks 3637
Faking busy work, remaining timers is 4, timer callbacks 7275
Faking busy work, remaining timers is 4, timer callbacks 10911
Faking busy work, remaining timers is 4, timer callbacks 14549
Faking busy work, remaining timers is 4, timer callbacks 18189
Faking busy work, remaining timers is 4, timer callbacks 21827
Faking busy work, remaining timers is 4, timer callbacks 25465
Faking busy work, remaining timers is 4, timer callbacks 29104
Faking busy work, remaining timers is 4, timer callbacks 32741
Faking busy work, remaining timers is 4, timer callbacks 36378
Faking busy work, remaining timers is 4, timer callbacks 40016
Faking busy work, remaining timers is 4, timer callbacks 43651
Faking busy work, remaining timers is 4, timer callbacks 47287
Faking busy work, remaining timers is 4, timer callbacks 50922
Faking busy work, remaining timers is 4, timer callbacks 54556
Faking busy work, remaining timers is 4, timer callbacks 58191
Faking busy work, remaining timers is 4, timer callbacks 61827
Faking busy work, remaining timers is 4, timer callbacks 65466
Faking busy work, remaining timers is 4, timer callbacks 69105
Faking busy work, remaining timers is 4, timer callbacks 72745
Faking busy work, remaining timers is 4, timer callbacks 76386
One Tick Timer Train Done, took 10132 ms, busy loop ran 22 times
    Perfect delta 128 cycles or 128 us
Timer 0 max delta 129 cycles or 129 us, 0 late callbacks (0.0%)
RECORD: {"testcase":"one_tick_timer_train", "timer":0, "max_delta_cycles":129, "max_delta_us":129, "late_callbacks":0, "perfect_delta_cycles":128, "perfect_delta_us":128, "train_time_ms":10132, "busy_loops":22, "timers":4, "expected_callbacks":78125, "expected_time_ms":11000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":31250}
Timer 1 max delta 160 cycles or 160 us, 1 late callbacks (0.0%)
RECORD: {"testcase":"one_tick_timer_train", "timer":1, "max_delta_cycles":160, "max_delta_us":160, "late_callbacks":1, "perfect_delta_cycles":128, "perfect_delta_us":128, "train_time_ms":10132, "busy_loops":22, "timers":4, "expected_callbacks":78125, "expected_time_ms":11000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":31250}
Timer 2 max delta 131 cycles or 131 us, 0 late callbacks (0.0%)
RECORD: {"testcase":"one_tick_timer_train", "timer":2, "max_delta_cycles":131, "max_delta_us":131, "late_callbacks":0, "perfect_delta_cycles":128, "perfect_delta_us":128, "train_time_ms":10132, "busy_loops":22, "timers":4, "expected_callbacks":78125, "expected_time_ms":11000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":31250}
Timer 3 max delta 130 cycles or 130 us, 0 late callbacks (0.0%)
RECORD: {"testcase":"one_tick_timer_train", "timer":3, "max_delta_cycles":130, "max_delta_us":130, "late_callbacks":0, "perfect_delta_cycles":128, "perfect_delta_us":128, "train_time_ms":10132, "busy_loops":22, "timers":4, "expected_callbacks":78125, "expected_time_ms":11000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":31250}
!! Some ticks were missed.
!! Consider making CONFIG_SYS_CLOCK_TICKS_PER_SEC smaller.
!! The busy loop didn't run as much as expected.
!! Consider making CONFIG_SYS_CLOCK_TICKS_PER_SEC smaller.
 PASS - test_one_tick_timer_train in 10.302 seconds
===================================================================
TESTSUITE timer_tick_train succeeded

------ TESTSUITE SUMMARY START ------

SUITE FAIL -   0.00% [timer_jitter_drift]: pass = 0, fail = 2, skip = 0, total = 2 duration = 20.860 seconds
 - FAIL - [timer_jitter_drift.test_jitter_drift_timer_period] duration = 10.430 seconds
 - FAIL - [timer_jitter_drift.test_jitter_drift_timer_startdelay] duration = 10.430 seconds

SUITE PASS - 100.00% [timer_tick_train]: pass = 1, fail = 0, skip = 0, total = 1 duration = 10.302 seconds
 - PASS - [timer_tick_train.test_one_tick_timer_train] duration = 10.302 seconds

------ TESTSUITE SUMMARY END ------

===================================================================
PROJECT EXECUTION FAILED

Environment (please complete the following information):

• OS: Ubuntu 20.04.1 LTS
• Toolchain Zephyr SDK 0.17.0
• Commit SHA or Version used: v4.1.0-2271-g68b2e7d677cc

[nordic-piks]

Maybe tweaks at #74939 where not sufficient?

[nordic-segl]

Is this fixed with #93325?