Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

mec15xxevb_assy6853: ringbuffer testsuite failing once due to a timeout randomly when run multiple times. #42756

Closed
yerabolu opened this issue Feb 12, 2022 · 0 comments · Fixed by #42834
Closed

mec15xxevb_assy6853: ringbuffer testsuite failing once due to a timeout randomly when run multiple times. #42756

yerabolu opened this issue Feb 12, 2022 · 0 comments · Fixed by #42834
Assignees
@nashif
Labels
area: Tests Issues related to a particular existing or missing test bug The issue is a bug, or the PR is fixing a bug platform: Microchip MEC Microchip MEC Platform priority: low Low impact/importance bug

Comments

@yerabolu
Copy link
Contributor

Describe the bug
ringbuffer testsuite failing once due to a timeout randomly when run multiple times.

To Reproduce
Steps to reproduce the behavior:

  1. twister --hardware-map $HOME/mec1.file --device-testing -T tests/lib/ringbuffer/ -vvv
  2. Test needs to be run multiple times and test errors out with a timeout.

Logs and console output

*** Booting Zephyr OS build v3.0.0-rc2-39-g5094a6e08cee  ***
Running test suite test_ringbuffer_api
===================================================================
START - test_ringbuffer_init
PASS - test_ringbuffer_init in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_pow2
PASS - test_ringbuffer_declare_pow2 in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_size
PASS - test_ringbuffer_declare_size in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread
PASS - test_ringbuffer_put_get_thread in 0.43 seconds
===================================================================
START - test_ringbuffer_put_get_isr
PASS - test_ringbuffer_put_get_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread_isr
PASS - test_ringbuffer_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_discard
PASS - test_ringbuffer_put_get_discard in 0.1 seconds
===================================================================
START - test_ringbuffer_pow2_put_get_thread_isr
PASS - test_ringbuffer_pow2_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_size_put_get_thread_isr
PASS - test_ringbuffer_size_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_array_perf
PASS - test_ringbuffer_array_perf in 0.1 seconds
===================================================================
START - test_ringbuffer_partial_putting
PASS - test_ringbuffer_partial_putting in 0.3 seconds
===================================================================
START - test_ringbuffer_partial_getting
PASS - test_ringbuffer_partial_getting in 0.3 seconds
===================================================================
START - test_ring_buffer_main
PASS - test_ring_buffer_main in 0.1 seconds
===================================================================
START - test_ringbuffer_raw
PASS - test_ringbuffer_raw in 0.1 seconds
===================================================================
START - test_ringbuffer_alloc_put
PASS - test_ringbuffer_alloc_put in 0.1 seconds
===================================================================
START - test_byte_put_free
PASS - test_byte_put_free in 0.1 seconds
===================================================================
START - test_ringbuffer_equal_bufs
PASS - test_ringbuffer_equal_bufs in 0.1 seconds
===================================================================
START - test_capacity
PASS - test_capacity in 0.1 seconds
===================================================================
START - test_size
PASS - test_size in 0.1 seconds
===================================================================
START - test_peek
PASS - test_peek in 0.1 seconds
===================================================================
START - test_reset
PASS - test_reset in 0.1 seconds
===================================================================
START - test_ringbuffer_performance
1 byte put-get, avg cycles: 0
4 byte put-get, avg cycles: 0
1 byte put claim-finish, avg cycles: 0
5 byte put claim-finish, avg cycles: 0
5 byte get claim-finish, avg cycles: 0
PASS - test_ringbuffer_performance in 0.49 seconds
===================================================================
START - test_ringbuffer_concurrent
Ztress execution report:
context 0:
- executed:230, preempted:0
- ticks initial:20, optimized:16
context 1:
- executed:223, preempted:10
- ticks initial:20, optimized:16
Avarage CPU load:58%, measurements:2
PASS - test_ringbuffer_concurrent in 0.276 seconds
===================================================================
START - test_ringbuffer_zerocpy_stress
Producing interrupts consuming
4% remaining:9000 ms
12% remaining:8000 ms
20% remaining:7000 ms
28% remaining:6000 ms
34% remaining:5000 ms
42% remaining:4000 ms
50% remaining:3000 ms
58% remaining:2000 ms
66% remaining:1000 ms
74% remaining:0 ms
Ztress execution report:
context 0:
- executed:42575, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:39804, preempted:1480
- ticks initial:20, optimized:4
Avarage CPU load:60%, measurements:100
Consuming interrupts producing
0% remaining:9000 ms
0% remaining:8000 ms
0% remaining:7000 ms
0% remaining:6000 ms
0% remaining:5000 ms
0% remaining:4000 ms
0% remaining:3000 ms
0% remaining:2000 ms
0% remaining:1000 ms
0% remaining:0 ms
Ztress execution report:
context 0:
- executed:42226, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:42218, preempted:5
- ticks initial:20, optimized:4
Avarage CPU load:65%, measurements:100
PASS - test_ringbuffer_zerocpy_stress in 20.71 seconds
===================================================================
START - test_ringbuffer_cpy_stress
Producing interrupts consuming
*** Booting Zephyr OS build v3.0.0-rc2-39-g5094a6e08cee  ***
Running test suite test_ringbuffer_api
===================================================================
START - test_ringbuffer_init
PASS - test_ringbuffer_init in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_pow2
PASS - test_ringbuffer_declare_pow2 in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_size
PASS - test_ringbuffer_declare_size in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread
PASS - test_ringbuffer_put_get_thread in 0.43 seconds
===================================================================
START - test_ringbuffer_put_get_isr
PASS - test_ringbuffer_put_get_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread_isr
PASS - test_ringbuffer_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_discard
PASS - test_ringbuffer_put_get_discard in 0.1 seconds
===================================================================
START - test_ringbuffer_pow2_put_get_thread_isr
PASS - test_ringbuffer_pow2_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_size_put_get_thread_isr
PASS - test_ringbuffer_size_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_array_perf
PASS - test_ringbuffer_array_perf in 0.1 seconds
===================================================================
START - test_ringbuffer_partial_putting
PASS - test_ringbuffer_partial_putting in 0.3 seconds
===================================================================
START - test_ringbuffer_partial_getting
PASS - test_ringbuffer_partial_getting in 0.3 seconds
===================================================================
START - test_ring_buffer_main
PASS - test_ring_buffer_main in 0.1 seconds
===================================================================
START - test_ringbuffer_raw
PASS - test_ringbuffer_raw in 0.1 seconds
===================================================================
START - test_ringbuffer_alloc_put
PASS - test_ringbuffer_alloc_put in 0.1 seconds
===================================================================
START - test_byte_put_free
PASS - test_byte_put_free in 0.1 seconds
===================================================================
START - test_ringbuffer_equal_bufs
PASS - test_ringbuffer_equal_bufs in 0.1 seconds
===================================================================
START - test_capacity
PASS - test_capacity in 0.1 seconds
===================================================================
START - test_size
PASS - test_size in 0.1 seconds
===================================================================
START - test_peek
PASS - test_peek in 0.1 seconds
===================================================================
START - test_reset
PASS - test_reset in 0.1 seconds
===================================================================
START - test_ringbuffer_performance
1 byte put-get, avg cycles: 0
4 byte put-get, avg cycles: 0
1 byte put claim-finish, avg cycles: 0
5 byte put claim-finish, avg cycles: 0
5 byte get claim-finish, avg cycles: 0
PASS - test_ringbuffer_performance in 0.49 seconds
===================================================================
START - test_ringbuffer_concurrent
Ztress execution report:
context 0:
- executed:220, preempted:0
- ticks initial:20, optimized:16
context 1:
- executed:215, preempted:10
- ticks initial:20, optimized:16
Avarage CPU load:58%, measurements:2
PASS - test_ringbuffer_concurrent in 0.265 seconds
===================================================================
START - test_ringbuffer_zerocpy_stress
Producing interrupts consuming
3% remaining:9000 ms
9% remaining:8000 ms
14% remaining:7000 ms
19% remaining:6000 ms
24% remaining:5000 ms
29% remaining:4000 ms
34% remaining:3000 ms
40% remaining:2000 ms
45% remaining:1000 ms
50% remaining:0 ms
Ztress execution report:
context 0:
- executed:42743, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:40152, preempted:1018
- ticks initial:20, optimized:4
Avarage CPU load:59%, measurements:100
Consuming interrupts producing
0% remaining:9000 ms*** Booting Zephyr OS build v3.0.0-rc2-39-g5094a6e08cee  ***
Running test suite test_ringbuffer_api
===================================================================
START - test_ringbuffer_init
PASS - test_ringbuffer_init in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_pow2
PASS - test_ringbuffer_declare_pow2 in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_size
PASS - test_ringbuffer_declare_size in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread
PASS - test_ringbuffer_put_get_thread in 0.43 seconds
===================================================================
START - test_ringbuffer_put_get_isr
PASS - test_ringbuffer_put_get_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread_isr
PASS - test_ringbuffer_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_discard
PASS - test_ringbuffer_put_get_discard in 0.1 seconds
===================================================================
START - test_ringbuffer_pow2_put_get_thread_isr
PASS - test_ringbuffer_pow2_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_size_put_get_thread_isr
PASS - test_ringbuffer_size_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_array_perf
PASS - test_ringbuffer_array_perf in 0.1 seconds
===================================================================
START - test_ringbuffer_partial_putting
PASS - test_ringbuffer_partial_putting in 0.3 seconds
===================================================================
START - test_ringbuffer_partial_getting
PASS - test_ringbuffer_partial_getting in 0.3 seconds
===================================================================
START - test_ring_buffer_main
PASS - test_ring_buffer_main in 0.1 seconds
===================================================================
START - test_ringbuffer_raw
PASS - test_ringbuffer_raw in 0.1 seconds
===================================================================
START - test_ringbuffer_alloc_put
PASS - test_ringbuffer_alloc_put in 0.1 seconds
===================================================================
START - test_byte_put_free
PASS - test_byte_put_free in 0.1 seconds
===================================================================
START - test_ringbuffer_equal_bufs
PASS - test_ringbuffer_equal_bufs in 0.1 seconds
===================================================================
START - test_capacity
PASS - test_capacity in 0.1 seconds
===================================================================
START - test_size
PASS - test_size in 0.1 seconds
===================================================================
START - test_peek
PASS - test_peek in 0.1 seconds
===================================================================
START - test_reset
PASS - test_reset in 0.1 seconds
===================================================================
START - test_ringbuffer_performance
1 byte put-get, avg cycles: 0
4 byte put-get, avg cycles: 0
1 byte put claim-finish, avg cycles: 0
5 byte put claim-finish, avg cycles: 0
5 byte get claim-finish, avg cycles: 0
PASS - test_ringbuffer_performance in 0.49 seconds
===================================================================
START - test_ringbuffer_concurrent
Ztress execution report:
context 0:
- executed:208, preempted:0
- ticks initial:20, optimized:16
context 1:
- executed:202, preempted:10
- ticks initial:20, optimized:16
Avarage CPU load:58%, measurements:2
PASS - test_ringbuffer_concurrent in 0.254 seconds
===================================================================
START - test_ringbuffer_zerocpy_stress
Producing interrupts consuming
3% remaining:9000 ms
8% remaining:8000 ms
12% remaining:7000 ms
17% remaining:6000 ms
23% remaining:5000 ms
28% remaining:4000 ms
33% remaining:3000 ms
38% remaining:2000 ms
43% remaining:1000 ms
47% remaining:0 ms
Ztress execution report:
context 0:
- executed:42645, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:39957, preempted:953
- ticks initial:20, optimized:4
Avarage CPU load:63%, measurements:100
Consuming interrupts producing
0% remaining:9000 ms
0% remaining:8000 ms
0% remaining:7000 ms
0% remaining:6000 ms
0% remaining:5000 ms
0% remaining:4000 ms
0% remaining:3000 ms
0% remaining:2000 ms
0% remaining:1000 ms
0% remaining:0 ms
Ztress execution report:
context 0:
- executed:41863, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:41866, preempted:3
- ticks initial:20, optimized:4
Avarage CPU load:65%, measurements:100
PASS - test_ringbuffer_zerocpy_stress in 20.71 seconds
===================================================================
START - test_ringbuffer_cpy_stress
Producing interrupts consuming
0% remaining:9000 ms
0% remaining:8000 ms
0% remaining:7000 ms
0% remaining:6000 ms
0% remaining:5000 ms
0% remaining:4000 ms
0% remaining:3000 ms
0% remaining:2000 ms
0% remaining:1000 ms
0% remaining:0 ms
Ztress execution report:
context 0:
- executed:43510, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:42106, preempted:7
- ticks initial:20, optimized:4
Avarage CPU load:57%, measurements:100
Consuming interrupts producing
*** Booting Zephyr OS build v3.0.0-rc2-39-g5094a6e08cee  ***
Running test suite test_ringbuffer_api
===================================================================
START - test_ringbuffer_init
PASS - test_ringbuffer_init in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_pow2
PASS - test_ringbuffer_declare_pow2 in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_size
PASS - test_ringbuffer_declare_size in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread
PASS - test_ringbuffer_put_get_thread in 0.43 seconds
===================================================================
START - test_ringbuffer_put_get_isr
PASS - test_ringbuffer_put_get_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread_isr
PASS - test_ringbuffer_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_discard
PASS - test_ringbuffer_put_get_discard in 0.1 seconds
===================================================================
START - test_ringbuffer_pow2_put_get_thread_isr
PASS - test_ringbuffer_pow2_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_size_put_get_thread_isr
PASS - test_ringbuffer_size_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_array_perf
PASS - test_ringbuffer_array_perf in 0.1 seconds
===================================================================
START - test_ringbuffer_partial_putting
PASS - test_ringbuffer_partial_putting in 0.3 seconds
===================================================================
START - test_ringbuffer_partial_getting
PASS - test_ringbuffer_partial_getting in 0.3 seconds
===================================================================
START - test_ring_buffer_main
PASS - test_ring_buffer_main in 0.1 seconds
===================================================================
START - test_ringbuffer_raw
PASS - test_ringbuffer_raw in 0.1 seconds
===================================================================
START - test_ringbuffer_alloc_put
PASS - test_ringbuffer_alloc_put in 0.1 seconds
===================================================================
START - test_byte_put_free
PASS - test_byte_put_free in 0.1 seconds
===================================================================
START - test_ringbuffer_equal_bufs
PASS - test_ringbuffer_equal_bufs in 0.1 seconds
===================================================================
START - test_capacity
PASS - test_capacity in 0.1 seconds
===================================================================
START - test_size
PASS - test_size in 0.1 seconds
===================================================================
START - test_peek
PASS - test_peek in 0.1 seconds
===================================================================
START - test_reset
PASS - test_reset in 0.1 seconds
===================================================================
START - test_ringbuffer_performance
1 byte put-get, avg cycles: 0
4 byte put-get, avg cycles: 0
1 byte put claim-finish, avg cycles: 0
5 byte put claim-finish, avg cycles: 0
5 byte get claim-finish, avg cycles: 0
PASS - test_ringbuffer_performance in 0.49 seconds
===================================================================
START - test_ringbuffer_concurrent
Ztress execution report:
context 0:
- executed:230, preempted:0
- ticks initial:20, optimized:16
context 1:
- executed:223, preempted:10
- ticks initial:20, optimized:16
Avarage CPU load:58%, measurements:2
PASS - test_ringbuffer_concurrent in 0.276 seconds
===================================================================
START - test_ringbuffer_zerocpy_stress
Producing interrupts consuming
3% remaining:9000 ms
9% remaining:8000 ms
13% remaining:7000 ms
19% remaining:6000 ms
24% remaining:5000 ms
29% remaining:4000 ms
35% remaining:3000 ms
40% remaining:2000 ms
45% remaining:1000 ms
50% remaining:0 ms
Ztress execution report:
context 0:
- executed:42855, preempted:0
- ticks initial:20, optimized:4
context 1:
- executed:40251, preempted:1012
- ticks initial:20, optimized:4
Avarage CPU load:61%, measurements:100
Consuming interrupts producing
0% remaining:9000 ms*** Booting Zephyr OS build v3.0.0-rc2-39-g5094a6e08cee  ***
Running test suite test_ringbuffer_api
===================================================================
START - test_ringbuffer_init
PASS - test_ringbuffer_init in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_pow2
PASS - test_ringbuffer_declare_pow2 in 0.1 seconds
===================================================================
START - test_ringbuffer_declare_size
PASS - test_ringbuffer_declare_size in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread
PASS - test_ringbuffer_put_get_thread in 0.43 seconds
===================================================================
START - test_ringbuffer_put_get_isr
PASS - test_ringbuffer_put_get_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_thread_isr
PASS - test_ringbuffer_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_put_get_discard
PASS - test_ringbuffer_put_get_discard in 0.1 seconds
===================================================================
START - test_ringbuffer_pow2_put_get_thread_isr
PASS - test_ringbuffer_pow2_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_size_put_get_thread_isr
PASS - test_ringbuffer_size_put_get_thread_isr in 0.1 seconds
===================================================================
START - test_ringbuffer_array_perf
PASS - test_ringbuffer_array_perf in 0.1 seconds
===================================================================
START - test_ringbuffer_partial_putting
PASS - test_ringbuffer_partial_putting in 0.3 seconds
===================================================================
START - test_ringbuffer_partial_getting
PASS - test_ringbuffer_partial_getting in 0.3 seconds
===================================================================
START - test_ring_buffer_main
PASS - test_ring_buffer_main in 0.1 seconds
===================================================================
START - test_ringbuffer_raw
PASS - test_ringbuffer_raw in 0.1 seconds
===================================================================
START - test_ringbuffer_alloc_put
PASS - test_ringbuffer_alloc_put in 0.1 seconds
===================================================================
START - test_byte_put_free
PASS - test_byte_put_free in 0.1 seconds
===================================================================
START - test_ringbuffer_equal_bufs
PASS - test_ringbuffer_equal_bufs in 0.1 seconds
===================================================================
START - test_capacity
PASS - test_capacity in 0.1 seconds
===================================================================
START - test_size
PASS - test_size in 0.1 seconds
===================================================================
START - test_peek
PASS - test_peek in 0.1 seconds
===================================================================
START - test_reset
PASS - test_reset in 0.1 seconds
===================================================================
START - test_ringbuffer_performance
1 byte put-get, avg cycles: 0
4 byte put-get, avg cycles: 0
1 byte put claim-finish, avg cycles: 0
5 byte put claim-finish, avg cycles: 0
5 byte get claim-finish, avg cycles: 0
PASS - test_ringbuffer_performance in 0.49 seconds
===================================================================
START - test_ringbuffer_concurrent
Ztress execution report:
context 0:
- executed:220, preempted:0
- ticks initial:20, optimized:16
context 1:
- executed:215, preempted:10
- ticks initial:20, optimized:16
Avarage CPU load:58%, measurements:2
PASS - test_ringbuffer_concurrent in 0.265 seconds
===================================================================
START - test_ringbuffer_zerocpy_stress
Producing interrupts consuming

Environment (please complete the following information):

  • OS: Fedora
  • Toolchain : SDK 13.2
  • Commit SHA : 5094a6e
@yerabolu yerabolu added bug The issue is a bug, or the PR is fixing a bug platform: Microchip MEC Microchip MEC Platform labels Feb 12, 2022
@enjiamai enjiamai self-assigned this Feb 14, 2022
@dkalowsk dkalowsk added area: Tests Issues related to a particular existing or missing test priority: low Low impact/importance bug labels Feb 15, 2022
@dkalowsk dkalowsk assigned nashif and unassigned enjiamai Feb 15, 2022
nashif added a commit to nashif/zephyr that referenced this issue Feb 15, 2022
@nashif
tests: ringbuffer: increase timeout
b2fc760 
Increae timeout from 90 to 150 to make it pass on more slow boards.

Fixes zephyrproject-rtos#42756

Signed-off-by: Anas Nashif <anas.nashif@intel.com>
@nashif nashif mentioned this issue Feb 15, 2022
Merged
nashif added a commit that referenced this issue Feb 15, 2022
@nashif
tests: ringbuffer: increase timeout
73d8a8d 
Increae timeout from 90 to 150 to make it pass on more slow boards.

Fixes #42756

Signed-off-by: Anas Nashif <anas.nashif@intel.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nashif nashif

Labels
area: Tests Issues related to a particular existing or missing test bug The issue is a bug, or the PR is fixing a bug platform: Microchip MEC Microchip MEC Platform priority: low Low impact/importance bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

tests: ringbuffer: increase timeout nashif/zephyr
4 participants
@nashif @dkalowsk @enjiamai @yerabolu