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

tests/kernel/sched/schedule_api is failing after 0875740 on m2gl025_miv #30408

Closed
yingmingx opened this issue Dec 3, 2020 · 13 comments
Closed

tests/kernel/sched/schedule_api is failing after 0875740 on m2gl025_miv #30408

yingmingx opened this issue Dec 3, 2020 · 13 comments
Assignees
@andyross
Labels
area: Kernel bug The issue is a bug, or the PR is fixing a bug priority: medium Medium impact/importance bug

Comments

@yingmingx
Copy link
Collaborator

When I submit a new PR about scheduler testing, CI build error. So I resubmit a PR just add some notes to reconfirm the issue.
See #30379.
Maybe there are some bug on qemu arc platform.
@yingmingx yingmingx added the bug The issue is a bug, or the PR is fixing a bug label Dec 3, 2020
@yingmingx yingmingx changed the title CI build error on scheduler testing test：CI build error on scheduler testing Dec 3, 2020
@nashif
Copy link
Member

nashif commented Dec 3, 2020

@yingmingx Please submit bugs using the template and provide more context, pointing a PR that fails is not really needed if you can reproduce this locally and can provide the failure details directly here.

The issue:

The test tests/kernel/sched/schedule_api is failing after 0875740 on m2gl025_miv:

10:22:15.6576 [WARNING] plic: Unhandled write to offset 0x200000, value 0x0.
10:22:15.6633 [WARNING] uart: Unhandled write to offset 0xC. Unhandled bits: [0] when writing value 0x1. Tags: BIT8 (0x1).
10:22:15.6717 [DEBUG] uart: [+0.41s host +0.1ms virt 0.1ms virt from start] *** Booting Zephyr OS build zephyr-v2.4.0-1999-g349c50a6826d  ***
10:22:15.6762 [DEBUG] uart: [+4.53ms host +0.1ms virt 0.2ms virt from start]   Running test suite threads_scheduling
10:22:15.6767 [DEBUG] uart: [+0.49ms host +0s virt 0.2ms virt from start]   ===================================================================
10:22:15.6769 [DEBUG] uart: [+0.25ms host +0s virt 0.2ms virt from start]   START - test_bad_priorities
10:22:15.6809 [DEBUG] uart: [+3.94ms host +0.1ms virt 0.3ms virt from start]    PASS - test_bad_priorities
10:22:15.6813 [DEBUG] uart: [+0.5ms host +0s virt 0.3ms virt from start]   ===================================================================
10:22:15.6816 [DEBUG] uart: [+0.28ms host +0s virt 0.3ms virt from start]   START - test_priority_cooperative
10:22:15.6872 [DEBUG] uart: [+5.61ms host +1.2ms virt 1.5ms virt from start]    PASS - test_priority_cooperative
10:22:15.6878 [DEBUG] uart: [+0.51ms host +0s virt 1.5ms virt from start]   ===================================================================
10:22:15.6882 [DEBUG] uart: [+0.43ms host +0.1ms virt 1.6ms virt from start]   START - test_priority_preemptible
10:22:15.6908 [DEBUG] uart: [+2.61ms host +1.1ms virt 2.7ms virt from start]    PASS - test_priority_preemptible
10:22:15.6913 [DEBUG] uart: [+0.54ms host +0.1ms virt 2.8ms virt from start]   ===================================================================
10:22:15.6916 [DEBUG] uart: [+0.33ms host +0s virt 2.8ms virt from start]   START - test_priority_preemptible_wait_prio
10:22:15.6953 [DEBUG] uart: [+3.6ms host +0.7ms virt 3.5ms virt from start]    PASS - test_priority_preemptible_wait_prio
10:22:15.6957 [DEBUG] uart: [+0.49ms host +0s virt 3.5ms virt from start]   ===================================================================
10:22:15.6961 [DEBUG] uart: [+0.41ms host +0.1ms virt 3.6ms virt from start]   START - test_yield_cooperative
10:22:15.6975 [DEBUG] uart: [+1.31ms host +0.1ms virt 3.7ms virt from start]    PASS - test_yield_cooperative
10:22:15.6990 [DEBUG] uart: [+1.51ms host +0s virt 3.7ms virt from start]   ===================================================================
10:22:15.6992 [DEBUG] uart: [+0.24ms host +0s virt 3.7ms virt from start]   START - test_sleep_cooperative
10:22:15.7017 [DEBUG] uart: [+2.51ms host +1.1ms virt 4.8ms virt from start]    PASS - test_sleep_cooperative
10:22:15.7023 [DEBUG] uart: [+0.54ms host +0.1ms virt 4.9ms virt from start]   ===================================================================
10:22:15.7025 [DEBUG] uart: [+0.29ms host +0s virt 4.9ms virt from start]   START - test_sleep_wakeup_preemptible
10:22:15.7035 [DEBUG] uart: [+0.94ms host +0.1ms virt 5ms virt from start]    PASS - test_sleep_wakeup_preemptible
10:22:15.7040 [DEBUG] uart: [+0.49ms host +0s virt 5ms virt from start]   ===================================================================
10:22:15.7043 [DEBUG] uart: [+0.36ms host +0.1ms virt 5.1ms virt from start]   START - test_pending_thread_wakeup
10:22:15.7050 [DEBUG] uart: [+0.65ms host +0s virt 5.1ms virt from start]    PASS - test_pending_thread_wakeup
10:22:15.7056 [DEBUG] uart: [+0.6ms host +0.1ms virt 5.2ms virt from start]   ===================================================================
10:22:15.7059 [DEBUG] uart: [+0.31ms host +0s virt 5.2ms virt from start]   START - test_time_slicing_preemptible
10:22:15.9017 [DEBUG] uart: [+0.2s host +5.1ms virt 10.3ms virt from start]    PASS - test_time_slicing_preemptible
10:22:15.9032 [DEBUG] uart: [+1.48ms host +0s virt 10.3ms virt from start]   ===================================================================
10:22:15.9040 [DEBUG] uart: [+0.82ms host +0.1ms virt 10.4ms virt from start]   START - test_time_slicing_disable_preemptible
10:22:16.0938 [DEBUG] uart: [+0.19s host +5ms virt 15.4ms virt from start]    PASS - test_time_slicing_disable_preemptible
10:22:16.0944 [DEBUG] uart: [+0.61ms host +0.1ms virt 15.5ms virt from start]   ===================================================================
10:22:16.0947 [DEBUG] uart: [+0.32ms host +0s virt 15.5ms virt from start]   START - test_lock_preemptible
10:22:16.1353 [DEBUG] uart: [+40.5ms host +2.1ms virt 17.6ms virt from start]    PASS - test_lock_preemptible
10:22:16.1369 [DEBUG] uart: [+1.61ms host +0.1ms virt 17.7ms virt from start]   ===================================================================
10:22:16.1373 [DEBUG] uart: [+0.51ms host +0s virt 17.7ms virt from start]   START - test_unlock_preemptible
10:22:16.1743 [DEBUG] uart: [+36.89ms host +1ms virt 18.7ms virt from start]    PASS - test_unlock_preemptible
10:22:16.1749 [DEBUG] uart: [+0.66ms host +0.1ms virt 18.8ms virt from start]   ===================================================================
10:22:16.1752 [DEBUG] uart: [+0.32ms host +0s virt 18.8ms virt from start]   START - test_unlock_nested_sched_lock
10:22:16.2045 [DEBUG] uart: [+29.23ms host +1ms virt 19.8ms virt from start]    PASS - test_unlock_nested_sched_lock
10:22:16.2055 [DEBUG] uart: [+1.04ms host +0.1ms virt 19.9ms virt from start]   ===================================================================
10:22:16.2058 [DEBUG] uart: [+0.31ms host +0s virt 19.9ms virt from start]   START - test_sched_is_preempt_thread
10:22:16.2074 [DEBUG] uart: [+1.57ms host +0.1ms virt 20ms virt from start]    PASS - test_sched_is_preempt_thread
10:22:16.2079 [DEBUG] uart: [+0.58ms host +0.1ms virt 20.1ms virt from start]   ===============================================================
====
10:22:16.2081 [DEBUG] uart: [+0.21ms host +0s virt 20.1ms virt from start]   START - test_slice_reset
10:22:16.3803 [DEBUG] uart: [+0.17s host +18.6ms virt 38.7ms virt from start]    PASS - test_slice_reset
10:22:16.3819 [DEBUG] uart: [+1.64ms host +0.1ms virt 38.8ms virt from start]   ===============================================================
====
10:22:16.3824 [DEBUG] uart: [+0.5ms host +0s virt 38.8ms virt from start]   START - test_slice_scheduling
10:22:16.4075 [DEBUG] uart: [+25.11ms host +2ms virt 40.8ms virt from start]   A
10:22:16.4127 [DEBUG] uart: [+5.14ms host +0.1ms virt 40.9ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4128 [DEBUG] uart: [+0.18ms host +0s virt 40.9ms virt from start]
10:22:16.4136 [DEBUG] uart: [+0.81ms host +0.1ms virt 41ms virt from start]   B
10:22:16.4174 [DEBUG] uart: [+3.76ms host +0.1ms virt 41.1ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4174 [DEBUG] uart: [+61µs host +0s virt 41.1ms virt from start]
10:22:16.4178 [DEBUG] uart: [+0.34ms host +0s virt 41.1ms virt from start]   C
10:22:16.4215 [DEBUG] uart: [+3.76ms host +0.2ms virt 41.3ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4216 [DEBUG] uart: [+61µs host +0s virt 41.3ms virt from start]
10:22:16.4219 [DEBUG] uart: [+0.35ms host +0s virt 41.3ms virt from start]   D
10:22:16.4252 [DEBUG] uart: [+3.27ms host +0.1ms virt 41.4ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4253 [DEBUG] uart: [+46µs host +0s virt 41.4ms virt from start]
10:22:16.4256 [DEBUG] uart: [+0.39ms host +0.1ms virt 41.5ms virt from start]   E
10:22:16.4279 [DEBUG] uart: [+2.22ms host +0.1ms virt 41.6ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4279 [DEBUG] uart: [+45µs host +0s virt 41.6ms virt from start]
10:22:16.4282 [DEBUG] uart: [+0.33ms host +0.1ms virt 41.7ms virt from start]   F
10:22:16.4311 [DEBUG] uart: [+2.88ms host +0.1ms virt 41.8ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4311 [DEBUG] uart: [+47µs host +0s virt 41.8ms virt from start]
10:22:16.4314 [DEBUG] uart: [+0.25ms host +0s virt 41.8ms virt from start]   G
10:22:16.4337 [DEBUG] uart: [+2.33ms host +0.2ms virt 42ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/sch
edule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_id
x)) is false
10:22:16.4338 [DEBUG] uart: [+42µs host +0s virt 42ms virt from start]
10:22:16.4345 [DEBUG] uart: [+0.75ms host +0s virt 42ms virt from start]   H
10:22:16.4365 [DEBUG] uart: [+1.94ms host +0.1ms virt 42.1ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4365 [DEBUG] uart: [+44µs host +0s virt 42.1ms virt from start]
10:22:16.4368 [DEBUG] uart: [+0.31ms host +0.1ms virt 42.2ms virt from start]   I
10:22:16.4392 [DEBUG] uart: [+2.34ms host +0.1ms virt 42.3ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4392 [DEBUG] uart: [+38µs host +0s virt 42.3ms virt from start]
10:22:16.4394 [DEBUG] uart: [+0.21ms host +0s virt 42.3ms virt from start]
10:22:16.4394 [DEBUG] uart: [+32µs host +0s virt 42.3ms virt from start]
10:22:16.4413 [DEBUG] uart: [+1.91ms host +0.2ms virt 42.5ms virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/kernel/sched/s
chedule_api/src/test_slice_scheduling.c:61: thread_tslice: ((tdelta >= expected_slice_min) && (tdelta <= expected_slice_max) && (idx == thread_
idx)) is false
10:22:16.4414 [DEBUG] uart: [+34µs host +0s virt 42.5ms virt from start]
10:22:16.4418 [DEBUG] uart: [+0.39ms host +0s virt 42.5ms virt from start]    FAIL - test_slice_scheduling
10:22:16.4423 [DEBUG] uart: [+0.57ms host +0.1ms virt 42.6ms virt from start]   ===============================================================
====
10:22:16.4426 [DEBUG] uart: [+0.26ms host +0s virt 42.6ms virt from start]   START - test_priority_scheduling
10:22:16.4458 [DEBUG] uart: [+3.21ms host +0.4ms virt 43ms virt from start]   ABCDEFGHI
10:22:16.4491 [DEBUG] uart: [+3.26ms host +0.5ms virt 43.5ms virt from start]   ABCDEFGHI
10:22:16.4518 [DEBUG] uart: [+2.69ms host +0.6ms virt 44.1ms virt from start]   ABCDEFGHI
10:22:16.4550 [DEBUG] uart: [+3.18ms host +0.6ms virt 44.7ms virt from start]   ABCDEFGHI
:

@nashif nashif added the priority: high High impact/importance bug label Dec 3, 2020
@nashif nashif changed the title test：CI build error on scheduler testing tests/kernel/sched/schedule_api is failing after 0875740 on m2gl025_miv Dec 3, 2020
@yingmingx
Copy link
Collaborator Author

@nashif Your suggestion is helpful. I'll provide more information when I report bugs later.

This was referenced Dec 8, 2020
Merged
Merged
@nashif
Copy link
Member

nashif commented Jan 5, 2021

@andyross any updates on this?

@PerMac
Copy link
Member

PerMac commented Jan 11, 2021

This issue is a duplicate of #29705

@yingmingx
Copy link
Collaborator Author

Close this issue because this is duplicate of #29705

@yingmingx yingmingx reopened this Jan 25, 2021
@yingmingx
Copy link
Collaborator Author

@ PerMac This issue fail on test_slice_scheduling, but you mentioned issue #29705 failed on test_slice_reset. May be they are different.

@andyross
Copy link
Contributor

@yingmingx : This really does look like a duplicate of the timeslicing bug @ceolin has been working. There is a fix up at #30916 , can you try that please?

@nashif
Copy link
Member

nashif commented Jan 27, 2021

@andyross #30916 does not fix this bug, in fact, it is failing in CI on that PR

@yingmingx
Copy link
Collaborator Author

@andyross I patch ceolin's code on this testing PR #30379. It still failed.

INFO - 9/40 m2gl025_miv tests/kernel/sched/schedule_api/kernel.scheduler.multiq FAILED Failed (renode 9.791s)

@ceolin
Copy link
Member

ceolin commented Jan 28, 2021

@andyross I patch ceolin's code on this testing PR #30379. It still failed.

INFO - 9/40 m2gl025_miv tests/kernel/sched/schedule_api/kernel.scheduler.multiq FAILED Failed (renode 9.791s)

this target contains another problem that that pr does not fix indeed.

@andyross
Copy link
Contributor

It's a soc-level kconfig bug: #31726

Unfortunately with my toddler-level renode knowledge, all I can submit is a workaround. I'm not sure who the right owner should be.

@nashif nashif added priority: medium Medium impact/importance bug and removed priority: high High impact/importance bug labels Jan 28, 2021
@andyross
Copy link
Contributor

andyross commented Feb 1, 2021

There's a workaround patch (a full fix requires some work with renode configuration) at #31841

@andyross
Copy link
Contributor

andyross commented Feb 3, 2021

Close this, as the root cause and workaround are tracked in #31726

@andyross andyross closed this as completed Feb 3, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@andyross andyross

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

No branches or pull requests
5 participants
@nashif @andyross @ceolin @yingmingx @PerMac