search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.59k stars 6.48k forks source link

kernel: timer: timer_behavior: kernel.timer.timer fails #71863

Closed katgiadla closed 2 months ago

katgiadla commented 5 months ago

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

Observed on nrf5340dk/nrf5340/cpunet.

To Reproduce Steps to reproduce the behavior:

  1. have nrf5340dk/nrf5340/cpunet connected
  2. go to your zephyr dir
  3. call ./scripts/twister -T tests/kernel/timer/timer_behavior -p nrf5340dk/nrf5340/cpunet --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 v3.6.0-2817-gdbf62a5a2a84 ***
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 7 seconds
periodic timer samples gathered, calculating statistics
timer clock rate 32768, kernel tick rate 8192
expected period drift: 98.632812 us
period duration statistics for 7000 samples (0 rollovers):
expected: 1000 us,       32.768000 cycles
min:      1068.115234 us, 35 cycles
max:      1129.150391 us, 37 cycles
mean:     1098.632812 us, 36.000000 cycles
variance: 251.723187 us, 0.270286 cycles
stddev:   15.865787 us, 0.519890 cycles
timer start cycle 12261, end cycle 264261,
total time 7690429.687500 us, expected time 7000000.000000 us,
expected time drift 690429.687500 us, difference 0.000000 us
Assertion failed at ../../../../../../../zephyr/tests/kernel/timer/timer_behavior/src/jitter_drift.c:284: do_test_using: (stddev_us < (double)CONFIG_TIMER_TEST_MAX_STDDEV is false)
Standard deviation (in microseconds) outside expected bound
FAIL - test_jitter_drift_timer_period in 7.858 seconds
===================================================================
START - test_jitter_drift_timer_startdelay
periodic timer behavior test using explicit start with delay
collecting time samples for approx 7 seconds
periodic timer samples gathered, calculating statistics
timer clock rate 32768, kernel tick rate 8192
expected period drift: 98.632812 us
period duration statistics for 7000 samples (0 rollovers):
expected: 1000 us,       32.768000 cycles
min:      1098.632812 us, 36 cycles
max:      1098.632812 us, 36 cycles
mean:     1098.632812 us, 36.000000 cycles
variance: 0.000000 us, 0.000000 cycles
stddev:   0.000000 us, 0.000000 cycles
timer start cycle 270204, end cycle 522204,
total time 7690429.687500 us, expected time 7000000.000000 us,
expected time drift 690429.687500 us, difference 0.000000 us
PASS - test_jitter_drift_timer_startdelay in 7.829 seconds
===================================================================
TESTSUITE timer_jitter_drift failed.
Running TESTSUITE timer_tick_train
===================================================================
START - test_one_tick_timer_train
Initializing 4 Timers, Tick Rate 8192Hz, Expecting 20480 callbacks in 11000 ms
Starting Timers with Skews
Faking busy work, remaining timers is 4, timer callbacks 0
Faking busy work, remaining timers is 4, timer callbacks 684
Faking busy work, remaining timers is 4, timer callbacks 1367
Faking busy work, remaining timers is 4, timer callbacks 2051
Faking busy work, remaining timers is 4, timer callbacks 2734
Faking busy work, remaining timers is 4, timer callbacks 3418
Faking busy work, remaining timers is 4, timer callbacks 4102
Faking busy work, remaining timers is 4, timer callbacks 4785
Faking busy work, remaining timers is 4, timer callbacks 5469
Faking busy work, remaining timers is 4, timer callbacks 6152
Faking busy work, remaining timers is 4, timer callbacks 6836
Faking busy work, remaining timers is 4, timer callbacks 7519
Faking busy work, remaining timers is 4, timer callbacks 8202
Faking busy work, remaining timers is 4, timer callbacks 8886
Faking busy work, remaining timers is 4, timer callbacks 9569
Faking busy work, remaining timers is 4, timer callbacks 10253
Faking busy work, remaining timers is 4, timer callbacks 10937
Faking busy work, remaining timers is 4, timer callbacks 11621
Faking busy work, remaining timers is 4, timer callbacks 12305
Faking busy work, remaining timers is 4, timer callbacks 12989
Faking busy work, remaining timers is 4, timer callbacks 13673
Faking busy work, remaining timers is 4, timer callbacks 14356
Faking busy work, remaining timers is 4, timer callbacks 15040
Faking busy work, remaining timers is 4, timer callbacks 15723
Faking busy work, remaining timers is 4, timer callbacks 16407
Faking busy work, remaining timers is 4, timer callbacks 17090
Faking busy work, remaining timers is 4, timer callbacks 17774
Faking busy work, remaining timers is 4, timer callbacks 18458
Faking busy work, remaining timers is 4, timer callbacks 19142
Faking busy work, remaining timers is 4, timer callbacks 19825
One Tick Timer Train Done, took 10010 ms, busy loop ran 30 times
Perfect delta 16 cycles or 488 us
Timer 0 max delta 17 cycles or 519 us, 0 late callbacks (0.0%)
Timer 1 max delta 16 cycles or 488 us, 0 late callbacks (0.0%)
Timer 2 max delta 17 cycles or 519 us, 0 late callbacks (0.0%)
Timer 3 max delta 16 cycles or 488 us, 0 late callbacks (0.0%)
!! 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.061 seconds
===================================================================
TESTSUITE timer_tick_train succeeded
------ TESTSUITE SUMMARY START ------
SUITE FAIL -  50.00% [timer_jitter_drift]: pass = 1, fail = 1, skip = 0, total = 2 duration = 15.687 seconds
- FAIL - [timer_jitter_drift.test_jitter_drift_timer_period] duration = 7.858 seconds
- PASS - [timer_jitter_drift.test_jitter_drift_timer_startdelay] duration = 7.829 seconds
SUITE PASS - 100.00% [timer_tick_train]: pass = 1, fail = 0, skip = 0, total = 1 duration = 10.061 seconds
- PASS - [timer_tick_train.test_one_tick_timer_train] duration = 10.061 seconds
------ TESTSUITE SUMMARY END ------
===================================================================
RunID: 6df47e08978b6f7373e505a7011816f1
PROJECT EXECUTION FAILED

Environment (please complete the following information):

teburd commented 5 months ago

Perhaps related...

66075 #67833

This, like the ITE failure in particular also seems like... maybe just maybe it should be passing with the stddev allowance changed. I need to think about this some.

katgiadla commented 5 months ago

The same issue has occurred on nrf52dk/nrf52832 on version v3.6.0-2878-g4a5fa0169484.

katgiadla commented 4 months ago

The same issue has occured on nrf52840dk/nrf52840 on version v3.6.0-4666-g3a3f25c9a683.

FRASTM commented 3 months ago

test also fails with stm32l0 nucleo board nucleo_l073rz, on _timer_jitterdrift item

*** Booting Zephyr OS build v3.7.0-rc1-2-g4d0a8c1e8b83 ***
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 1 seconds
periodic timer samples gathered, calculating statistics
timer clock rate 32000000, kernel tick rate 10000
period duration statistics for 1000 samples (0 rollovers):
expected: 1000 us,          32000.000000 cycles
min:      900.000000 us,    28800 cycles
max:      1100.031250 us,   35201 cycles
mean:     1000.000094 us,   32000.003000 cycles
variance: 20.006255 us,     20486.404991 cycles
stddev:   4.472835 us,  143.130722 cycles
timer start cycle 891072, end cycle 32891075,
total time 1000000.093750 us, expected time 1000000.000000 us,
expected time drift 0.000000 us, difference 0.093750 us
RECORD: {"testcase":"jitter_drift_timer", "mechanism":"builtin", "stats_count":1000, "rollovers":0, "mean_us":1000.000094, "mean_cycles":32000, "stddev_us":4.472835, "stddev_cycles":143, "var_us":20.006255, "var_cycles":20486, "min_us":900.000000, "min_cycles":28800, "max_us":1100.031250, "max_cycles":35201, "timer_start_cycle": 891072, "timer_end_cycle": 32891075, "total_time_us":1000000.093750, "expected_total_time_us":1000000.000000, "expected_total_drift_us":0.000000, "total_drift_us":0.093750, "expected_period_cycles":32000, "expected_period_drift_us":0.000000, "sys_clock_hw_cycles_per_sec":32000000, "CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC":32000000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":10000, "CONFIG_TIMER_TEST_PERIOD":1000, "CONFIG_TIMER_TEST_SAMPLES":1000, "CONFIG_TIMER_TEST_MAX_STDDEV":10}
Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/timer/timer_behavior/src/jitter_drift.c:322: do_test_using: (max_us <= max_us_bound is false)
Longest timer period too long (off by more than expected 10%)
FAIL - test_jitter_drift_timer_period in 1.261 seconds
===================================================================
START - test_jitter_drift_timer_startdelay
periodic timer behavior test using explicit start with delay
collecting time samples for approx 1 seconds
periodic timer samples gathered, calculating statistics
timer clock rate 32000000, kernel tick rate 10000
period duration statistics for 1000 samples (0 rollovers):
expected: 1000 us,          32000.000000 cycles
min:      900.000000 us,    28800 cycles
max:      1100.031250 us,   35201 cycles
mean:     1000.000094 us,   32000.003000 cycles
variance: 20.006255 us,     20486.404991 cycles
stddev:   4.472835 us,  143.130722 cycles
timer start cycle 41706466, end cycle 73706469,
total time 1000000.093750 us, expected time 1000000.000000 us,
expected time drift 0.000000 us, difference 0.093750 us
RECORD: {"testcase":"jitter_drift_timer", "mechanism":"startdelay", "stats_count":1000, "rollovers":0, "mean_us":1000.000094, "mean_cycles":32000, "stddev_us":4.472835, "stddev_cycles":143, "var_us":20.006255, "var_cycles":20486, "min_us":900.000000, "min_cycles":28800, "max_us":1100.031250, "max_cycles":35201, "timer_start_cycle": 41706466, "timer_end_cycle": 73706469, "total_time_us":1000000.093750, "expected_total_time_us":1000000.000000, "expected_total_drift_us":0.000000, "total_drift_us":0.093750, "expected_period_cycles":32000, "expected_period_drift_us":0.000000, "sys_clock_hw_cycles_per_sec":32000000, "CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC":32000000, "CONFIG_SYS_CLOCK_TICKS_PER_SEC":10000, "CONFIG_TIMER_TEST_PERIOD":1000, "CONFIG_TIMER_TEST_SAMPLES":1000, "CONFIG_TIMER_TEST_MAX_STDDEV":10}
Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/timer/timer_behavior/src/jitter_drift.c:322: do_test_using: (max_us <= max_us_bound is false)
Longest timer period too long (off by more than expected 10%)
FAIL - test_jitter_drift_timer_startdelay in 1.262 seconds
===================================================================
TESTSUITE timer_jitter_drift failed.
...

TESTSUITE timer_tick_train succeeded
------ TESTSUITE SUMMARY START ------
SUITE FAIL -   0.00% [timer_jitter_drift]: pass = 0, fail = 2, skip = 0, total = 2 duration = 2.523 seconds
- FAIL - [timer_jitter_drift.test_jitter_drift_timer_period] duration = 1.261 seconds
- FAIL - [timer_jitter_drift.test_jitter_drift_timer_startdelay] duration = 1.262 seconds
SUITE PASS - 100.00% [timer_tick_train]: pass = 1, fail = 0, skip = 0, total = 1 duration = 10.322 seconds
- PASS - [timer_tick_train.test_one_tick_timer_train] duration = 10.322 seconds
------ TESTSUITE SUMMARY END ------
===================================================================
RunID: 1de2533fa232463b131c3ae74230257c
PROJECT EXECUTION FAILED

For that particular target board, which has a CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC at 32MHz, a CONFIG_SYS_CLOCK_TICKS_PER_SEC lower than 10000 can fix the problem