tests/kernel/threads/no-multithreading/: Single/Repeated delay boot banner

[cinlyooi-intel]

Describe the bug
Instead of seeing "It works", we see single/multiple '***** delaying boot 1000ms (per build configuration) *****'

To Reproduce
Steps to reproduce the behavior:

1. mkdir build; cd build
2. cmake -DBOARD=sam_e70_xplained
3. make
4. make run

Replace -DBOARD=sam_e70_xplained withquark_se_c1000_ss_devboard(arc)
Screenshots or console output
sam_e70_xplained:

***** delaying boot 1000ms (per build configuration) *****
***** delaying boot 1000ms (per build configuration) *****
***** delaying boot 1000ms (per build configuration) *****
***** delaying boot 1000ms (per build configuration) *****
***** delaying boot 1000ms (per build configuration) *****
***** delaying boot 1000ms (per build configuration) *****
***** delaying boot 1000ms (per build configuration) *****

quark_se_c1000_ss_devboard:arc:

***** delaying boot 1000ms (per build configuration) *****

Environment (please complete the following information):

• OS: fedora
• Toolchain: zephyr
• Commit SHA or Version used: 6368ed4

Additional context
Add any other context about the problem here.

[aurel32]

The loop on the SAM E70 board is due to the watchdog. The interrupts are not served anymore, so the watchdog fires.

Note that the test passes when not using a delayed boot.

[andrewboie]

@aurel32 the delay takes place in init's bg_thread_main(), before it calls application main(). interrupts are not locked when this is happening. why would busy-looping here cause the watchdog to fail? what kicks the dog? is there some high-priority watchdog thread that needs to be started?

[aurel32]

@andrewboie The watchdog is not the cause of the issue, it triggers after ~15 seconds. I was just trying to explain the difference between the two boards. Adding this 1 second delay causes other parts of the code to enter in an endless loop and prevents the watchdog ISR to be serviced. Disabling the watchdog on the SAM E70 boards doesn't fix the issue it just makes both boards to hang with a similar behavior.

[andrewboie]

prevents the watchdog ISR to be serviced.

Out of curiosity, What is supposed to service it?

Eventually the watchdog resets the system. But this always happens, if I don't enable the boot delay I just see the test succeed, then reset, and run again, succeed, reset, ad nauseum. Interrupts aren't locked. My feeling is that with watchdog enabled, unless there is a thread created to service it, the test will reset after 15 seconds no matter what is happening. Since this is a test with no threads we should disable the watchdog for this test. Or is it the driver that is supposed to service the watchdog?

Having said all that, watchdog aside, I think the real bug here is that k_busy_wait() is supposed to return after 1000ms and it just sits there forever instead.

[andrewboie]

Yeah k_busy_wait() is broken, with this debug printout:

diff --git a/kernel/thread.c b/kernel/thread.c
index 5f8cab4883..4a0722a069 100644
--- a/kernel/thread.c
+++ b/kernel/thread.c
@@ -112,6 +112,9 @@ void z_impl_k_busy_wait(u32_t usec_to_wait)
 
        for (;;) {
                u32_t current_cycles = k_cycle_get_32();
+               printk("start: %u current: %u delta: %u waiting for: %u\n",
+                      start_cycles, current_cycles,
+                      current_cycles - start_cycles, cycles_to_wait);
 
                /* this handles the rollover on an unsigned 32-bit value */
                if ((current_cycles - start_cycles) >= cycles_to_wait) {

I get output:

start: 1509844 current: 4042057 delta: 2532213 waiting for: 300000000
start: 1509844 current: 5882373 delta: 4372529 waiting for: 300000000
start: 1509844 current: 4722698 delta: 3212854 waiting for: 300000000
start: 1509844 current: 3563021 delta: 2053177 waiting for: 300000000
start: 1509844 current: 5403337 delta: 3893493 waiting for: 300000000
start: 1509844 current: 4243658 delta: 2733814 waiting for: 300000000
start: 1509844 current: 3083983 delta: 1574139 waiting for: 300000000
start: 1509844 current: 4924291 delta: 3414447 waiting for: 300000000
start: 1509844 current: 3764616 delta: 2254772 waiting for: 300000000
start: 1509844 current: 5604942 delta: 4095098 waiting for: 300000000
start: 1509844 current: 4445247 delta: 2935403 waiting for: 300000000
start: 1509844 current: 3285568 delta: 1775724 waiting for: 300000000
start: 1509844 current: 5125892 delta: 3616048 waiting for: 300000000
start: 1509844 current: 3966211 delta: 2456367 waiting for: 300000000
start: 1509844 current: 5806535 delta: 4296691 waiting for: 300000000
start: 1509844 current: 4646856 delta: 3137012 waiting for: 300000000
start: 1509844 current: 3487177 delta: 1977333 waiting for: 300000000
start: 1509844 current: 5327485 delta: 3817641 waiting for: 300000000
start: 1509844 current: 4167810 delta: 2657966 waiting for: 300000000
start: 1509844 current: 3008135 delta: 1498291 waiting for: 300000000
start: 1509844 current: 4848455 delta: 3338611 waiting for: 300000000
start: 1509844 current: 3688772 delta: 2178928 waiting for: 300000000
start: 1509844 current: 5529090 delta: 4019246 waiting for: 300000000
start: 1509844 current: 4369411 delta: 2859567 waiting for: 300000000
start: 1509844 current: 3209728 delta: 1699884 waiting for: 300000000
start: 1509844 current: 5050040 delta: 3540196 waiting for: 300000000
start: 1509844 current: 3890365 delta: 2380521 waiting for: 300000000
start: 1509844 current: 5730687 delta: 4220843 waiting for: 300000000
start: 1509844 current: 4571006 delta: 3061162 waiting for: 300000000
start: 1509844 current: 3411317 delta: 1901473 waiting for: 300000000
start: 1509844 current: 5251635 delta: 3741791 waiting for: 300000000
start: 1509844 current: 4091960 delta: 2582116 waiting for: 300000000
start: 1509844 current: 5932284 delta: 4422440 waiting for: 300000000
start: 1509844 current: 4772593 delta: 3262749 waiting for: 300000000
start: 1509844 current: 3612918 delta: 2103074 waiting for: 300000000
start: 1509844 current: 5453240 delta: 3943396 waiting for: 300000000
start: 1509844 current: 4293565 delta: 2783721 waiting for: 300000000
start: 1509844 current: 3133874 delta: 1624030 waiting for: 300000000
start: 1509844 current: 4974194 delta: 3464350 waiting for: 300000000
start: 1509844 current: 3814519 delta: 2304675 waiting for: 300000000
start: 1509844 current: 5654841 delta: 4144997 waiting for: 300000000
start: 1509844 current: 4495150 delta: 2985306 waiting for: 300000000
start: 1509844 current: 3335471 delta: 1825627 waiting for: 300000000
start: 1509844 current: 5175795 delta: 3665951 waiting for: 300000000
start: 1509844 current: 4016120 delta: 2506276 waiting for: 300000000
start: 1509844 current: 5856436 delta: 4346592 waiting for: 300000000
start: 1509844 current: 4696745 delta: 3186901 waiting for: 300000000
start: 1509844 current: 3537066 delta: 2027222 waiting for: 300000000
start: 1509844 current: 5377384 delta: 3867540 waiting for: 300000000
start: 1509844 current: 4217709 delta: 2707865 waiting for: 300000000
start: 1509844 current: 3058028 delta: 1548184 waiting for: 300000000
start: 1509844 current: 4898344 delta: 3388500 waiting for: 300000000
start: 1509844 current: 3738665 delta: 2228821 waiting for: 300000000
start: 1509844 current: 5578995 delta: 4069151 waiting for: 300000000
start: 1509844 current: 4419310 delta: 2909466 waiting for: 300000000
start: 1509844 current: 3259623 delta: 1749779 waiting for: 300000000
start: 1509844 current: 5099939 delta: 3590095 waiting for: 300000000

k_cycle_get_32() seems to wrap around at some upper bound far less than what is needed for the loop to ever break.

[andrewboie]

I noticed that when CONFIG_MULTITHREADING=n, I get no timer interrupts. This doesn't seem right. No wonder things aren't working.

What's happening is the main thread is running with interrupts disabled. @andyross fixed this: #9668

And then later it was reverted along with a bunch of other stuff by @nashif :
#9808

The tree is now in a bad state. We still support disabling multithreading, but a lot of work towards fixing it was taken out, and the feature is essentially broken. We need to restore them, or finish removing the feature.

[andrewboie]

After much discussion on slack, it seems clear that several people are strongly opposed to disabling this for 1.14, even temporarily.

@cinlyooi-intel @inakypg @nashif Is CONFIG_BOOT_BANNER a hard requirement for hardware testing?

[inakypg]

After much discussion on slack, it seems clear that several people are strongly opposed to disabling this for 1.14, even temporarily.

@cinlyooi-intel @inakypg @nashif Is CONFIG_BOOT_BANNER a hard requirement for hardware testing?

It is highly desirable, because it allows us to detect if we saw all the output; the test runner will verify if it got all of the expected messages. If the first one is missing, something might be stinking (early missing console because who knows).

This, for example, catches a lot in ESP32, we loose a lot of early console and it is not clear yet why.

[what the hell -- sorry, by mistake I edited your comment instead of replying to it -- fixed, blame to -ENOCOFFEE ]