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: test_timeout_order in tests/kernel/common assertion failed #34585

Closed
yerabolu opened this issue Apr 27, 2021 · 8 comments · Fixed by #35275
Closed

mec15xxevb_assy6853: test_timeout_order in tests/kernel/common assertion failed #34585

yerabolu opened this issue Apr 27, 2021 · 8 comments · Fixed by #35275
Assignees
@dcpleung @scottwcpg
Labels
bug The issue is a bug, or the PR is fixing a bug platform: Microchip MEC Microchip MEC Platform priority: medium Medium impact/importance bug

Comments

@yerabolu
Copy link
Contributor

yerabolu commented Apr 27, 2021 •
edited
Loading

Describe the bug
test_timeout_order in tests/kernel/common assertion failed

It is also failing on EHL_CRB

To Reproduce
Steps to reproduce the behavior:

  1. twister --hardware-map ~/mec1.file --device-testing -T tests/kernel/common/
  2. See error

Expected behavior
Test should pass

Logs and console output

EBUG   - DEVICE: ***** delaying boot 500ms (per build configuration) *****
DEBUG   - DEVICE: *** Booting Zephyr OS build zephyr-v2.5.0-2578-ge366d7948a53  (delayed boot 500ms) ***
DEBUG   - DEVICE: Running test suite common
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_bootdelay
DEBUG   - DEVICE: PASS - test_bootdelay in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_irq_offload
DEBUG   - DEVICE: PASS - test_irq_offload in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_byteorder_memcpy_swap
DEBUG   - DEVICE: PASS - test_byteorder_memcpy_swap in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_byteorder_mem_swap
DEBUG   - DEVICE: PASS - test_byteorder_mem_swap in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be64
DEBUG   - DEVICE: PASS - test_sys_get_be64 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be64
DEBUG   - DEVICE: PASS - test_sys_put_be64 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be48
DEBUG   - DEVICE: PASS - test_sys_get_be48 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be48
DEBUG   - DEVICE: PASS - test_sys_put_be48 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be32
DEBUG   - DEVICE: PASS - test_sys_get_be32 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be32
DEBUG   - DEVICE: PASS - test_sys_put_be32 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be24
DEBUG   - DEVICE: PASS - test_sys_get_be24 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be24
DEBUG   - DEVICE: PASS - test_sys_put_be24 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_be16
DEBUG   - DEVICE: PASS - test_sys_get_be16 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_be16
DEBUG   - DEVICE: PASS - test_sys_put_be16 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le16
DEBUG   - DEVICE: PASS - test_sys_get_le16 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le16
DEBUG   - DEVICE: PASS - test_sys_put_le16 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le24
DEBUG   - DEVICE: PASS - test_sys_get_le24 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le24
DEBUG   - DEVICE: PASS - test_sys_put_le24 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le32
DEBUG   - DEVICE: PASS - test_sys_get_le32 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le32
DEBUG   - DEVICE: PASS - test_sys_put_le32 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le48
DEBUG   - DEVICE: PASS - test_sys_get_le48 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le48
DEBUG   - DEVICE: PASS - test_sys_put_le48 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_get_le64
DEBUG   - DEVICE: PASS - test_sys_get_le64 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_sys_put_le64
DEBUG   - DEVICE: PASS - test_sys_put_le64 in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_atomic
DEBUG   - DEVICE: PASS - test_atomic in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_bitfield
DEBUG   - DEVICE: SKIP - test_bitfield in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_printk
DEBUG   - DEVICE: 22 113 10000 32768 40000 22
DEBUG   - DEVICE: p 112 -10000 -32768 -40000 -22
DEBUG   - DEVICE: 0x1 0x01 0x0001 0x00000001 0x0000000000000001
DEBUG   - DEVICE: 0x1 0x 1 0x   1 0x       1
DEBUG   - DEVICE: 42 42 0042 00000042
DEBUG   - DEVICE: -42 -42 -042 -0000042
DEBUG   - DEVICE: 42 42   42       42
DEBUG   - DEVICE: 42 42 0042 00000042
DEBUG   - DEVICE: 255     42    abcdef        42
DEBUG   - DEVICE: 68719476735 -1 18446744073709551615 ffffffffffffffff
DEBUG   - DEVICE: 0xcafebabe 0xbeef 0x2a
DEBUG   - DEVICE: PASS - test_printk in 0.31 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_timeout_order
DEBUG   - DEVICE:
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/common/src/timeout_order.c:92: test_timeout_order: (poll_events[ii].state not equal to K_POLL_STATE_SEM_AVAILABLE)
DEBUG   - DEVICE:
DEBUG   - DEVICE: FAIL - test_timeout_order in 0.116 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_clock_uptime
DEBUG   - DEVICE: PASS - test_clock_uptime in 0.12 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_clock_cycle
DEBUG   - DEVICE: PASS - test_clock_cycle in 0.3 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_version
DEBUG   - DEVICE: PASS - test_version in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_multilib
DEBUG   - DEVICE: PASS - test_multilib in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_thread_context
DEBUG   - DEVICE: PASS - test_thread_context in 0.31 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_errno
DEBUG   - DEVICE: PASS - test_errno in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_ms_time_duration
DEBUG   - DEVICE: PASS - test_ms_time_duration in 0.182 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_bounds_check_mitigation
DEBUG   - DEVICE: PASS - test_bounds_check_mitigation in 0.1 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: Test suite common failed.
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: PROJECT EXECUTION FAILED

Environment (please complete the following information):

  • OS: Fedora 29
  • SDK: zephyr-sdk-0.12.4
  • Commit SHA: e366d79
@yerabolu yerabolu added the bug The issue is a bug, or the PR is fixing a bug label Apr 27, 2021
@ioannisg ioannisg added the priority: medium Medium impact/importance bug label Apr 27, 2021
@scottwcpg
Copy link
Collaborator

Reproduced on MEC152x EVB building only the tests/kernel/common.
Not related to power management. Fails with PM disabled in build.
It will pass if I lower the CPU clock speed from full speed 48 MHz to 12 MHz. This implies this SoC is not able to update fast enough. The build is configured to use a 32 KHz clock for the kernel timer with second 48 MHz timer used for higher resolution.
Were there any changes in the kernel timing logic?

@scottwcpg
Copy link
Collaborator

Narrowed it down to something related to the 32KHz timer we are using for the kernel timer. If the build is switched to SYSTICK the test passes even at fastest CPU speed.

@scottwcpg
Copy link
Collaborator

@albertofloyd This is an issue. If we have to switch to SYSTICK then deep sleep will require enabling a 32 KHz based timer and the issues converting kernel ticks to 32 KHz units.

@scottwcpg
Copy link
Collaborator

@yerabolu and @ioannisg
The commit a09b5ad remoted a printk() from the spawned thread speeding up thread completion. Adding a the printk() back or a delay loop writing a read-only HW register allows the test to pass but causes the test application to trigger a fault after all tests have finished. Tried increasing thread stack size by setting CONFIG_TEST_EXTRA_STACKSIZE = 512. Tests all pass but still get fault when test program done.
Are other platforms using a 32 KHz kernel timer failing this test?

@albertofloyd
Copy link
Collaborator

@yerabolu was this test passing before? Do you have any any regression data?
Does the test have any CPU requirements?

@yerabolu
Copy link
Contributor Author

yerabolu commented Apr 28, 2021 •
edited
Loading

@yerabolu was this test passing before? Do you have any any regression data?
Does the test have any CPU requirements?

@albertofloyd and @scottwcpg: Yes this test was passing before and started failing from c22df64. After bisecting a09b5ad is the first bad commit.

@albertofloyd
Copy link
Collaborator

Thanks @yerabolu . That commit seems to be part of this PR #33302 introduced by as part of tickeless idle removal.

I;m not clear in the implications from tickeless removal to the RTOS drivers @andyross @nashif could you indicate if preliminary analysis from @scottwcpg is going in the direction expected by Zephyr.

@nashif
Copy link
Member

nashif commented May 11, 2021

the commit above is not related to tickless idle, tickless idle is not related to tickless kernel. Out kernel is tickless by default, this was the mode we had before introducing tickless kernel.

@LeiW000 LeiW000 added the platform: Microchip MEC Microchip MEC Platform label May 13, 2021
@dcpleung dcpleung mentioned this issue May 13, 2021
Merged
dcpleung added a commit to dcpleung/zephyr that referenced this issue May 14, 2021
@dcpleung
tests: kernel/common: incorrect use of k_poll in timeout order
338cf9a 
In the timeout order test, the usage of k_poll() assumes that it
only returns after all events are ready. However, that is not
the case, as k_poll() returns when non-zero number of events are
ready. This means the check for all semaphore being ready after
k_poll() will not always pass. So instead of using k_poll(),
simply wait a bit for timers to fire, then check results.

Also add some bits to clean up at the end of test.

Fixes zephyrproject-rtos#34585

Signed-off-by: Daniel Leung <[email protected]>
galak pushed a commit that referenced this issue May 25, 2021
@dcpleung @galak
tests: kernel/common: incorrect use of k_poll in timeout order
8fd3d18 
In the timeout order test, the usage of k_poll() assumes that it
only returns after all events are ready. However, that is not
the case, as k_poll() returns when non-zero number of events are
ready. This means the check for all semaphore being ready after
k_poll() will not always pass. So instead of using k_poll(),
simply wait a bit for timers to fire, then check results.

Also add some bits to clean up at the end of test.

Fixes #34585

Signed-off-by: Daniel Leung <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dcpleung dcpleung

@scottwcpg scottwcpg

Labels
bug The issue is a bug, or the PR is fixing a bug platform: Microchip MEC Microchip MEC Platform priority: medium Medium impact/importance bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

tests: kernel/common: incorrect use of k_poll in timeout order dcpleung/zephyr
7 participants
@nashif @ioannisg @albertofloyd @yerabolu @dcpleung @scottwcpg @LeiW000