SCHED_DEADLINE tasks causing WARNING at kernel/sched/sched.h message

SCHED_DEADLINE tasks causing WARNING at kernel/sched/sched.h message

[Marcel Ziswiler]

Hi

As part of our trustable work [1], we also run a lot of real time scheduler (SCHED_DEADLINE) tests on the
mainline Linux kernel (v6.16.2 in below reported case). Apart from some regression identified which recently
got fixed [2], the Linux scheduler proves quite capable of scheduling deadline tasks down to a granularity of
5ms on both of our test systems (amd64-based Intel NUCs and aarch64-based RADXA ROCK5Bs).

However, very rarely (e.g. only once over the course of the 2.4 billion tests we ran last week on ROCK5B), we
do get the following message in the logs.

Aug 23 18:09:37 localhost kernel: ------------[ cut here ]------------
Aug 23 18:09:37 localhost kernel: WARNING: CPU: 7 PID: 259143 at kernel/sched/sched.h:1787
__task_rq_lock+0xac/0xfc
Aug 23 18:09:37 localhost kernel: Modules linked in: ghash_generic overlay snd_soc_hdmi_codec panthor
rockchipdrm pwm_fan rfkill_gpio phy_rockchip_usbdp cdc_ether typec synopsys_hdmirx display_connector
snd_soc_simple_card hantro_vpu usbnet phy_rockchip_naneng_combphy phy_rockchip_samsung_hdptx rockchip_thermal
snd_soc_es8316 drm_gpuvm rtc_hym8563 rk805_pwrkey rockchip_saradc drm_exec industrialio_triggered_buffer
drm_shmem_helper kfifo_buf dw_hdmi_qp spi_rockchip_sfc analogix_dp gpu_sched dw_mipi_dsi drm_dp_aux_bus dw_hdmi
cec drm_display_helper snd_soc_rockchip_i2s_tdm cfg80211 drm_client_lib r8152 drm_dma_helper drm_kms_helper
v4l2_vp9 mii v4l2_h264 v4l2_jpeg v4l2_mem2mem snd_soc_audio_graph_card snd_soc_simple_card_utils rfkill
pci_endpoint_test drm dm_mod snd_aloop backlight dax
Aug 23 18:09:37 localhost kernel: CPU: 7 UID: 0 PID: 259143 Comm: stress-ng-cpu-s Not tainted 6.16.2-dirty #1
PREEMPT_RT 
Aug 23 18:09:37 localhost kernel: Hardware name: radxa Radxa ROCK 5 Model B/Radxa ROCK 5 Model B, BIOS 2024.07-
00925-g459560000736 07/01/2024
Aug 23 18:09:37 localhost kernel: pstate: 804000c9 (Nzcv daIF +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
Aug 23 18:09:37 localhost kernel: pc : __task_rq_lock+0xac/0xfc
Aug 23 18:09:37 localhost kernel: lr : __task_rq_lock+0x54/0xfc
Aug 23 18:09:37 localhost kernel: sp : ffff80009dd83b80
Aug 23 18:09:37 localhost kernel: x29: ffff80009dd83b80 x28: ffff0001e4855780 x27: 0000000000000000
Aug 23 18:09:37 localhost kernel: x26: 0000000000000000 x25: 0000000000000000 x24: ffffb2e0b0d37c60
Aug 23 18:09:37 localhost kernel: x23: ffff80009dd83bc8 x22: ffff0001e4855780 x21: ffff0001e4855780
Aug 23 18:09:37 localhost kernel: x20: ffffb2e0b0c2fe40 x19: ffff0002fef2ae40 x18: 0000000000000000
Aug 23 18:09:37 localhost kernel: x17: 0000000000000000 x16: 0000000000000000 x15: 0000ffffd2453db8
Aug 23 18:09:37 localhost kernel: x14: ffff0001e4855800 x13: 0000000000000000 x12: 0000000000000000
Aug 23 18:09:37 localhost kernel: x11: 0000000000000165 x10: ffff000100a5fce8 x9 : 0000000000000000
Aug 23 18:09:37 localhost kernel: x8 : 0000000000000000 x7 : ffff0001e4855800 x6 : 000000000000008f
Aug 23 18:09:37 localhost kernel: x5 : 0000000000000000 x4 : 0000000000000000 x3 : 0000000000000000
Aug 23 18:09:37 localhost kernel: x2 : 0000000000000001 x1 : ffff0002fef17258 x0 : ffffb2e0b0d5bfb0
Aug 23 18:09:37 localhost kernel: Call trace:
Aug 23 18:09:37 localhost kernel:  __task_rq_lock+0xac/0xfc (P)
Aug 23 18:09:37 localhost kernel:  rt_mutex_setprio+0x6c/0x498
Aug 23 18:09:37 localhost kernel:  rt_mutex_slowunlock+0x17c/0x310
Aug 23 18:09:37 localhost kernel:  rt_spin_unlock+0x7c/0x90
Aug 23 18:09:37 localhost kernel:  cpuset_cpus_allowed+0xd8/0x10c
Aug 23 18:09:37 localhost kernel:  __sched_setaffinity+0xb0/0x194
Aug 23 18:09:37 localhost kernel:  sched_setaffinity+0x140/0x27c
Aug 23 18:09:37 localhost kernel:  __arm64_sys_sched_setaffinity+0xb8/0x180
Aug 23 18:09:37 localhost kernel:  invoke_syscall+0x48/0x104
Aug 23 18:09:37 localhost kernel:  el0_svc_common.constprop.0+0xc0/0xe0
Aug 23 18:09:37 localhost kernel:  do_el0_svc+0x1c/0x28
Aug 23 18:09:37 localhost kernel:  el0_svc+0x34/0x104
Aug 23 18:09:37 localhost kernel:  el0t_64_sync_handler+0x10c/0x138
Aug 23 18:09:37 localhost kernel:  el0t_64_sync+0x198/0x19c
Aug 23 18:09:37 localhost kernel: ---[ end trace 0000000000000000 ]---

Usually, this is accompanied by our test workload process also getting the SIGXCPU signal, despite it not
overrunning its allocated runtime, at least not on purpose.

We are wondering what exactly could cause this or what exactly could be the issue.

We are happy to provide more detailed debugging information (however, full journal logs are usually a couple
hundred MB in size), but are looking for suggestions on how/what exactly to look at.

Any help is much appreciated. Thanks!

Cheers

Marcel

[1] https://projects.eclipse.org/projects/technology.tsf
[2] https://lore.kernel.org/all/ce8469c4fb2f3e2ada74add22cce4bfe61fd5bab.camel@codethink.co.uk
[3] https://lore.kernel.org/all/20250715071658.267-1-ziqianlu@bytedance.com
[4] https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/kernel/sched/sched.h?h=v6.16.2#n1785

BTW: due to us having applied this patch set on top of v6.16.2 [3] the line number moved by 2 lines so the
WARN_ON line in questions is actually the following [4].

Re: SCHED_DEADLINE tasks causing WARNING at kernel/sched/sched.h message

[Marcel Ziswiler]

Hi

On Tue, 2025-09-02 at 16:06 +0200, Marcel Ziswiler wrote:
> As part of our trustable work [1], we also run a lot of real time scheduler (SCHED_DEADLINE) tests on the
> mainline Linux kernel (v6.16.2 in below reported case).

Looking through more logs from earlier test runs I found similar WARN_ONs dating back as early as v6.15.3. So
it does not look like a "new" issue in that sense.

[snip]

Any help is much appreciated. Thanks!

Cheers

Marcel

Re: SCHED_DEADLINE tasks causing WARNING at kernel/sched/sched.h message

[Juri Lelli]

Hi Marcel,

On 02/09/25 18:49, Marcel Ziswiler wrote:
> Hi
> 
> On Tue, 2025-09-02 at 16:06 +0200, Marcel Ziswiler wrote:
> > As part of our trustable work [1], we also run a lot of real time scheduler (SCHED_DEADLINE) tests on the
> > mainline Linux kernel (v6.16.2 in below reported case).
> 
> Looking through more logs from earlier test runs I found similar WARN_ONs dating back as early as v6.15.3. So
> it does not look like a "new" issue in that sense.
> 
> [snip]
> 
> Any help is much appreciated. Thanks!

What's the actual workload composition leading the warning. I noticed
stress-ng in the report. Could you please share more details?

Thanks!
Juri

Re: SCHED_DEADLINE tasks causing WARNING at kernel/sched/sched.h message

[Marcel Ziswiler]

Hi Juri

Thanks for getting back to me and sorry for my late reply.

On Thu, 2025-09-04 at 11:22 +0200, Juri Lelli wrote:
> Hi Marcel,
> 
> On 02/09/25 18:49, Marcel Ziswiler wrote:
> > Hi
> > 
> > On Tue, 2025-09-02 at 16:06 +0200, Marcel Ziswiler wrote:
> > > As part of our trustable work [1], we also run a lot of real time scheduler (SCHED_DEADLINE) tests on the
> > > mainline Linux kernel (v6.16.2 in below reported case).
> > 
> > Looking through more logs from earlier test runs I found similar WARN_ONs dating back as early as v6.15.3.
> > So
> > it does not look like a "new" issue in that sense.
> > 
> > [snip]
> > 
> > Any help is much appreciated. Thanks!
> 
> What's the actual workload composition leading the warning. I noticed
> stress-ng in the report. Could you please share more details?

Yes, sure. It's actually the exact same workload as related to the regression I reported back in April [1].

We currently use three cores as follows:

#### core x

|sched_deadline = sched_period | sched_runtime | CP max run time 90% of sched_runtime | utilisation | reclaim |
| -- | -- | -- | -- | -- |
|  5 ms  | 0.15 ms | 0.135 ms |  3.00% | no |
| 10 ms  | 1.8 ms  | 1.62 ms  | 18.00% | no |
| 10 ms  | 2.1 ms  | 1.89 ms  | 21.00% | no |
| 14 ms  | 2.3 ms  | 2.07 ms  | 16.43% | no |
| 50 ms  | 8.0 ms  | 7.20 ms  | 16:00% | no |
| 10 ms  | 0.5 ms  | **1      |  5.00% | no |

Total utilisation of core x is 79.43% (less than 100%)

**1 - this shall be a rogue process. This process will
 a) run for the maximum allowed workload value 
 b) do not collect execution data

#### core y

|sched_deadline = sched_period | sched_runtime | CP max run time 90% of sched_runtime | utilisation | reclaim |
| -- | -- | -- | -- | -- |
|  5 ms  | 0.5 ms | 0.45 ms | 10.00% | no |
| 10 ms  | 1.9 ms | 1.71 ms | 19.00% | no |
| 12 ms  | 1.8 ms | 1.62 ms | 15.00% | no |
| 50 ms  | 5.5 ms | 4.95 ms | 11.00% | no |
| 50 ms  | 9.0 ms | 8.10 ms | 18.00% | no |

Total utilisation of core y is 73.00% (less than 100%)

#### core z

The third core is special as it will run 50 jobs with the same configuration as such:

|sched_deadline = sched_period | sched_runtime | CP max run time 90% of sched_runtime | utilisation |
| -- | -- | -- | -- |
|  50 ms  | 0.8 ms | 0.72 ms | 1.60% |

jobs 1-50 should run with reclaim OFF

Total utilisation of core y is 1.6 * 50 = 80.00% (less than 100%)

In addition to that main workload we also run further stressors like from the stress-ng suite. However, only on
the remaining cores and in a controlled nsjail/apparmor sandbox.

Please let me know if you need any further details which may help figuring out what exactly is going on.

> Thanks!
> Juri

Cheers

Marcel

[1] https://lore.kernel.org/all/f532441d8b3cf35e7058305fd9cd3f2cbd3a9fac.camel@codethink.co.uk

Re: SCHED_DEADLINE tasks causing WARNING at kernel/sched/sched.h message

[Juri Lelli]

On 12/09/25 12:03, Marcel Ziswiler wrote:
> Hi Juri
> 
> Thanks for getting back to me and sorry for my late reply.
> 
> On Thu, 2025-09-04 at 11:22 +0200, Juri Lelli wrote:
> > Hi Marcel,
> > 
> > On 02/09/25 18:49, Marcel Ziswiler wrote:
> > > Hi
> > > 
> > > On Tue, 2025-09-02 at 16:06 +0200, Marcel Ziswiler wrote:
> > > > As part of our trustable work [1], we also run a lot of real time scheduler (SCHED_DEADLINE) tests on the
> > > > mainline Linux kernel (v6.16.2 in below reported case).
> > > 
> > > Looking through more logs from earlier test runs I found similar WARN_ONs dating back as early as v6.15.3.
> > > So
> > > it does not look like a "new" issue in that sense.
> > > 
> > > [snip]
> > > 
> > > Any help is much appreciated. Thanks!
> > 
> > What's the actual workload composition leading the warning. I noticed
> > stress-ng in the report. Could you please share more details?
> 
> Yes, sure. It's actually the exact same workload as related to the regression I reported back in April [1].

Ah, OK. So it's the workload I reproduced (with rt-app) while working on
fixing that issues, and I didn't hit the WARN.

I am thinking that we might try to get more info about what's going on
by adding some trace_printks for balance callbacks and then stopping
tracing in case a WARN is hit.

Could you please, with the following, start tracing for sched_switch,
sched_migrate_task and sched_wakeup and add traceoff_on_warning to
kernel cmdline. Then share what was collected.

Thanks!
Juri

---
 kernel/sched/core.c  | 4 ++++
 kernel/sched/sched.h | 2 ++
 2 files changed, 6 insertions(+)

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index da2062de97a2..7b32828b94bc 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -5011,6 +5011,7 @@ static void do_balance_callbacks(struct rq *rq, struct balance_callback *head)
 		head->next = NULL;
 		head = next;
 
+		trace_printk("cpu=%d callback=%pS\n", rq->cpu, func);
 		func(rq);
 	}
 }
@@ -8211,6 +8212,7 @@ static void balance_push(struct rq *rq)
 	/*
 	 * Ensure the thing is persistent until balance_push_set(.on = false);
 	 */
+	trace_printk("cpu=%d callback=%pS\n", rq->cpu, &balance_push_callback);
 	rq->balance_callback = &balance_push_callback;
 
 	/*
@@ -8273,8 +8275,10 @@ static void balance_push_set(int cpu, bool on)
 	rq_lock_irqsave(rq, &rf);
 	if (on) {
 		WARN_ON_ONCE(rq->balance_callback);
+		trace_printk("cpu=%d on=%d callback=%pS\n", rq->cpu, on, &balance_push_callback);
 		rq->balance_callback = &balance_push_callback;
 	} else if (rq->balance_callback == &balance_push_callback) {
+		trace_printk("cpu=%d on=%d callback=%pS\n", rq->cpu, on, NULL);
 		rq->balance_callback = NULL;
 	}
 	rq_unlock_irqrestore(rq, &rf);
diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
index b5367c514c14..f91fc2d36c81 100644
--- a/kernel/sched/sched.h
+++ b/kernel/sched/sched.h
@@ -1963,6 +1963,8 @@ queue_balance_callback(struct rq *rq,
 	if (unlikely(head->next || rq->balance_callback == &balance_push_callback))
 		return;
 
+	trace_printk("cpu=%d callback=%pS\n", rq->cpu, func);
+
 	head->func = func;
 	head->next = rq->balance_callback;
 	rq->balance_callback = head;
--