Timeslicing is broken #14096
Description
Describe the bug
I created a simple debug app to test timeslicing. Two threads are created both preemptible with priority of 0. Both in the loop are printing a log and execute k_busy_loop(100000) (full code below). I expect that these two threads will be executed in round-robin fashion and I will see logs from both threads.
Now what I see is that at the beginning everything is fine for random time (usually from 10s to 60s) and then everything stops. When I execute from debugger I get following trace:
(gdb) bt
#0 k_cpu_idle () at /home/pdunaj/work/ncs/zephyr/arch/arm/core/cpu_idle.S:139
#1 0x00001f5a in _SysFatalErrorHandler (reason=<optimized out>, pEsf=<optimized out>) at /home/pdunaj/work/ncs/zephyr/arch/arm/core/sys_fatal_error_handler.c:70
#2 0x00001a42 in _oops () at /home/pdunaj/work/ncs/zephyr/arch/arm/core/swap_helper.S:380
#3 <signal handler called>
#4 0x20003958 in timeout_list ()
#5 0x00030100 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
It seems that issue is easier to replicate if I set the timeslice to 1 ms. Usually there are no logs at all. When run from debugger I see following trace:
#150 log_output_flush (log_output=log_output@entry=0x59fc <log_output>) at /home/pdunaj/work/ncs/zephyr/subsys/logging/log_output.c:142
#151 0x00001118 in panic (backend=<optimized out>) at /home/pdunaj/work/ncs/zephyr/subsys/logging/log_backend_rtt.c:241
#152 0x00000c5e in log_backend_panic (backend=<optimized out>) at ../../../include/logging/log_backend.h:176
#153 log_panic () at /home/pdunaj/work/ncs/zephyr/subsys/logging/log_core.c:397
#154 0x00001c40 in _Fault (esf=0x1ffffe68, exc_return=<optimized out>) at /home/pdunaj/work/ncs/zephyr/arch/arm/core/fault.c:676
#155 0x00001eae in __usage_fault () at /home/pdunaj/work/ncs/zephyr/arch/arm/core/fault_s.S:147
#156 <signal handler called>
#157 0x20003958 in timeout_list ()
#158 0x00030100 in ?? ()
To Reproduce
Steps to reproduce the behavior:
Build and run app as below. I run it on nrf52840_PCA10056.
Expected behavior
Scheduling must be stable.
Impact
Showstopper for anybody willing to use slicing and preemption.
Screenshots or console output
N/A
Environment (please complete the following information):
ncs zephyr 1d6219f from cf85618
Additional context
main.c:
#include <zephyr.h>
#include <misc/util.h>
#include <logging/log.h>
LOG_MODULE_REGISTER(sched_demo, 4);
#define THREAD_COUNT 2
#define STACK_SIZE 1024
static K_THREAD_STACK_ARRAY_DEFINE(stack, THREAD_COUNT, STACK_SIZE);
static struct k_thread thread[THREAD_COUNT];
static void thread_fn(void *p1, void *p2, void *p3)
{
size_t id = (size_t)p1;
while (true) {
LOG_INF("%zu: %p", id, k_current_get());
k_busy_wait(100000);
}
}
void main(void)
{
for (size_t i = 0; i < ARRAY_SIZE(thread); i++) {
k_thread_create(&thread[i],
stack[i], STACK_SIZE,
(k_thread_entry_t)thread_fn,
(void *)i, NULL, NULL,
K_PRIO_PREEMPT(0), 0, K_NO_WAIT);
LOG_INF("Thread %zu created", i);
}
LOG_INF("Start");
}
prj.conf
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
CONFIG_HEAP_MEM_POOL_SIZE=4096
CONFIG_SYS_CLOCK_TICKS_PER_SEC=1000
CONFIG_NUM_COOP_PRIORITIES=20
CONFIG_NUM_PREEMPT_PRIORITIES=20
CONFIG_TIMESLICE_SIZE=100
CONFIG_SPEED_OPTIMIZATIONS=y
CONFIG_ASSERT=y
CONFIG_ASSERT_LEVEL=2
CONFIG_SYS_POWER_MANAGEMENT=n
CONFIG_LOG=y
CONFIG_LOG_DEFAULT_LEVEL=2
CONFIG_LOG_PRINTK=y
CONFIG_LOG_IMMEDIATE=y
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_RTT_MODE_DROP=y
CONFIG_LOG_BACKEND_RTT_MESSAGE_SIZE=128
CONFIG_LOG_BACKEND_RTT_BUFFER=0
CONFIG_LOG_BACKEND_SHOW_COLOR=y
CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=y
CONFIG_CONSOLE=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_SEGGER_RTT_BUFFER_SIZE_UP=4096
CONFIG_RTT_CONSOLE=y
CONFIG_UART_CONSOLE=n