~90s reboot delay with v6.19 and PREEMPT_RT

~90s reboot delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Since linux v6.19 I noticed that rebooting my MSI Alpha 15 Laptop
would hang for about ~90s before rebooting. I bisected this (from
v6.18 to v6.19) and got this as the first bad commit:
9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")

Reverting this commit fixes the reboot delay but introduces these error (which
also seem to make the system crash sometimes):
[    T0] BUG: scheduling while atomic: swapper/0/0/0x00000002

Compiling the kernel without PREEMPT_RT also fixes the issue.

I've test these commits from "git log --oneline v6.19 kernel/cgroup"

This commit shows the reboot delay:
9311e6c29b34 cgroup: Fix sleeping from invalid context warning on PREEMPT_RT
These commits show no reboot delay, but "scheduling while atomic" warnings
and instability:
be04e96ba911 cgroup/cpuset: Globally track isolated_cpus update
b1034a690129 cgroup/cpuset: Ensure domain isolated CPUs stay in root or isolated partition
6cfeddbf4ade cgroup/cpuset: Move up prstate_housekeeping_conflict() helper
103b08709e8a cgroup/cpuset: Fail if isolated and nohz_full don't leave any housekeeping
55939cf28a48 cgroup/cpuset: Rename update_unbound_workqueue_cpumask() to update_isolation_cpumasks()
b66c7af4d86d cgroup: use credential guards in cgroup_attach_permissions()
d245698d727a cgroup: Defer task cgroup unlink until after the task is done switching out
This commit shows neither the reboot delay nor the "scheduling while atomic" problem:
260fbcb92bbe cgroup: Move dying_tasks cleanup from cgroup_task_release() to cgroup_task_free()

Bert Karwatzki

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Calvin Owens]

On Thursday 02/19 at 17:46 +0100, Bert Karwatzki wrote:
> Since linux v6.19 I noticed that rebooting my MSI Alpha 15 Laptop
> would hang for about ~90s before rebooting. I bisected this (from
> v6.18 to v6.19) and got this as the first bad commit:
> 9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
> 
> Reverting this commit fixes the reboot delay but introduces these error (which
> also seem to make the system crash sometimes):
> [    T0] BUG: scheduling while atomic: swapper/0/0/0x00000002
> 
> Compiling the kernel without PREEMPT_RT also fixes the issue.

Hi Bert,

I'm not seeing this behavior, there must be more to it than just this.

Could you share your kconfig? The dmesg with initcall_debug will be more
verbose during shutdown too, that may also help.

Thanks,
Calvin

> I've test these commits from "git log --oneline v6.19 kernel/cgroup"
> 
> This commit shows the reboot delay:
> 9311e6c29b34 cgroup: Fix sleeping from invalid context warning on PREEMPT_RT
> These commits show no reboot delay, but "scheduling while atomic" warnings
> and instability:
> be04e96ba911 cgroup/cpuset: Globally track isolated_cpus update
> b1034a690129 cgroup/cpuset: Ensure domain isolated CPUs stay in root or isolated partition
> 6cfeddbf4ade cgroup/cpuset: Move up prstate_housekeeping_conflict() helper
> 103b08709e8a cgroup/cpuset: Fail if isolated and nohz_full don't leave any housekeeping
> 55939cf28a48 cgroup/cpuset: Rename update_unbound_workqueue_cpumask() to update_isolation_cpumasks()
> b66c7af4d86d cgroup: use credential guards in cgroup_attach_permissions()
> d245698d727a cgroup: Defer task cgroup unlink until after the task is done switching out
> This commit shows neither the reboot delay nor the "scheduling while atomic" problem:
> 260fbcb92bbe cgroup: Move dying_tasks cleanup from cgroup_task_release() to cgroup_task_free()
> 
> Bert Karwatzki

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Donnerstag, dem 19.02.2026 um 12:53 -0800 schrieb Calvin Owens:
> On Thursday 02/19 at 17:46 +0100, Bert Karwatzki wrote:
> > Since linux v6.19 I noticed that rebooting my MSI Alpha 15 Laptop
> > would hang for about ~90s before rebooting. I bisected this (from
> > v6.18 to v6.19) and got this as the first bad commit:
> > 9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
> > 
> > Reverting this commit fixes the reboot delay but introduces these error (which
> > also seem to make the system crash sometimes):
> > [    T0] BUG: scheduling while atomic: swapper/0/0/0x00000002
> > 
> > Compiling the kernel without PREEMPT_RT also fixes the issue.
> 
> Hi Bert,
> 
> I'm not seeing this behavior, there must be more to it than just this.
> 
> Could you share your kconfig? The dmesg with initcall_debug will be more
> verbose during shutdown too, that may also help.

I tested v6.19 with initcall_debug and I'm seeing these messages (on startup, there
no extra message during the 90s reboot delay). I put the .config as an attachement in
a gitlab issue (Or should I put it in the mail? It's ~6500 lines):

https://gitlab.freedesktop.org/-/project/26509/uploads/8d1c04bbe0ab121945be7c898d08e1b6/config-6.19.0-stable

2026-02-19T23:37:50.140437+01:00 lisa kernel: [   T16] BUG: sleeping function called from invalid context at kernel/printk/printk.c:3377
2026-02-19T23:37:50.140439+01:00 lisa kernel: [   T16] in_atomic(): 0, irqs_disabled(): 0, non_block: 0, pid: 16, name: pr/legacy
2026-02-19T23:37:50.140441+01:00 lisa kernel: [   T16] preempt_count: 0, expected: 0
2026-02-19T23:37:50.140443+01:00 lisa kernel: [   T16] RCU nest depth: 1, expected: 0
2026-02-19T23:37:50.140445+01:00 lisa kernel: [   T16] CPU: 1 UID: 0 PID: 16 Comm: pr/legacy Tainted: G        W           6.19.0-stable #1159
PREEMPT_{RT,(full)} 
2026-02-19T23:37:50.140446+01:00 lisa kernel: [   T16] Tainted: [W]=WARN
2026-02-19T23:37:50.140448+01:00 lisa kernel: [   T16] Hardware name: Micro-Star International Co., Ltd. Alpha 15 B5EEK/MS-158L, BIOS E158LAMS.10F 11/11/2024
2026-02-19T23:37:50.140456+01:00 lisa kernel: [   T16] Call Trace:
2026-02-19T23:37:50.140458+01:00 lisa kernel: [   T16]  <TASK>
2026-02-19T23:37:50.140460+01:00 lisa kernel: [   T16]  dump_stack_lvl+0x4b/0x70
2026-02-19T23:37:50.140461+01:00 lisa kernel: [   T16]  __might_resched.cold+0xaf/0xbd
2026-02-19T23:37:50.140463+01:00 lisa kernel: [   T16]  console_conditional_schedule+0x26/0x30
2026-02-19T23:37:50.140464+01:00 lisa kernel: [   T16]  fbcon_redraw+0x9b/0x240
2026-02-19T23:37:50.140466+01:00 lisa kernel: [   T16]  ? get_color+0x21/0x130
2026-02-19T23:37:50.140468+01:00 lisa kernel: [   T16]  fbcon_scroll+0x165/0x1c0
2026-02-19T23:37:50.140470+01:00 lisa kernel: [   T16]  con_scroll+0xf6/0x200
2026-02-19T23:37:50.140472+01:00 lisa kernel: [   T16]  ? srso_alias_return_thunk+0x5/0xfbef5
2026-02-19T23:37:50.140474+01:00 lisa kernel: [   T16]  lf+0x9f/0xb0
2026-02-19T23:37:50.140475+01:00 lisa kernel: [   T16]  vt_console_print+0x2ff/0x460
2026-02-19T23:37:50.140477+01:00 lisa kernel: [   T16]  console_flush_one_record+0x21c/0x3e0
2026-02-19T23:37:50.140479+01:00 lisa kernel: [   T16]  ? console_flush_one_record+0x3e0/0x3e0
2026-02-19T23:37:50.140481+01:00 lisa kernel: [   T16]  legacy_kthread_func+0xc7/0x1a0
2026-02-19T23:37:50.140482+01:00 lisa kernel: [   T16]  ? housekeeping_affine+0x30/0x30
2026-02-19T23:37:50.140484+01:00 lisa kernel: [   T16]  kthread+0xf7/0x1e0
2026-02-19T23:37:50.140486+01:00 lisa kernel: [   T16]  ? kthreads_online_cpu+0x100/0x100
2026-02-19T23:37:50.140487+01:00 lisa kernel: [   T16]  ? kthreads_online_cpu+0x100/0x100
2026-02-19T23:37:50.140489+01:00 lisa kernel: [   T16]  ret_from_fork+0x20e/0x240
2026-02-19T23:37:50.140491+01:00 lisa kernel: [   T16]  ? kthreads_online_cpu+0x100/0x100
2026-02-19T23:37:50.140492+01:00 lisa kernel: [   T16]  ret_from_fork_asm+0x11/0x20
2026-02-19T23:37:50.140494+01:00 lisa kernel: [   T16]  </TASK>

and

2026-02-19T23:37:50.338878+01:00 lisa kernel: [   T16] BUG: sleeping function called from invalid context at kernel/printk/printk.c:3377
2026-02-19T23:37:50.338880+01:00 lisa kernel: [   T16] in_atomic(): 0, irqs_disabled(): 0, non_block: 0, pid: 16, name: pr/legacy
2026-02-19T23:37:50.338882+01:00 lisa kernel: [   T16] preempt_count: 0, expected: 0
2026-02-19T23:37:50.338884+01:00 lisa kernel: [   T16] RCU nest depth: 1, expected: 0
2026-02-19T23:37:50.338893+01:00 lisa kernel: [   T16] CPU: 7 UID: 0 PID: 16 Comm: pr/legacy Tainted: G        W           6.19.0-stable #1159
PREEMPT_{RT,(full)} 
2026-02-19T23:37:50.338895+01:00 lisa kernel: [   T16] Tainted: [W]=WARN
2026-02-19T23:37:50.338896+01:00 lisa kernel: [   T16] Hardware name: Micro-Star International Co., Ltd. Alpha 15 B5EEK/MS-158L, BIOS E158LAMS.10F 11/11/2024
2026-02-19T23:37:50.338897+01:00 lisa kernel: [   T16] Call Trace:
2026-02-19T23:37:50.338899+01:00 lisa kernel: [   T16]  <TASK>
2026-02-19T23:37:50.338901+01:00 lisa kernel: [   T16]  dump_stack_lvl+0x4b/0x70
2026-02-19T23:37:50.338906+01:00 lisa kernel: [   T16]  __might_resched.cold+0xaf/0xbd
2026-02-19T23:37:50.338908+01:00 lisa kernel: [   T16]  console_conditional_schedule+0x26/0x30
2026-02-19T23:37:50.338910+01:00 lisa kernel: [   T16]  fbcon_redraw+0x9b/0x240
2026-02-19T23:37:50.338916+01:00 lisa kernel: [   T16]  ? get_color+0x21/0x130
2026-02-19T23:37:50.338917+01:00 lisa kernel: [   T16]  fbcon_scroll+0x165/0x1c0
2026-02-19T23:37:50.338919+01:00 lisa kernel: [   T16]  con_scroll+0xf6/0x200
2026-02-19T23:37:50.338924+01:00 lisa kernel: [   T16]  ? srso_alias_return_thunk+0x5/0xfbef5
2026-02-19T23:37:50.338935+01:00 lisa kernel: [   T16]  lf+0x9f/0xb0
2026-02-19T23:37:50.338937+01:00 lisa kernel: [   T16]  vt_console_print+0x2ff/0x460
2026-02-19T23:37:50.338957+01:00 lisa kernel: [   T16]  console_flush_one_record+0x21c/0x3e0
2026-02-19T23:37:50.338960+01:00 lisa kernel: [   T16]  ? console_flush_one_record+0x3e0/0x3e0
2026-02-19T23:37:50.338962+01:00 lisa kernel: [   T16]  legacy_kthread_func+0xc7/0x1a0
2026-02-19T23:37:50.338964+01:00 lisa kernel: [   T16]  ? housekeeping_affine+0x30/0x30
2026-02-19T23:37:50.338965+01:00 lisa kernel: [   T16]  kthread+0xf7/0x1e0
2026-02-19T23:37:50.338966+01:00 lisa kernel: [   T16]  ? kthreads_online_cpu+0x100/0x100
2026-02-19T23:37:50.338968+01:00 lisa kernel: [   T16]  ? kthreads_online_cpu+0x100/0x100
2026-02-19T23:37:50.338972+01:00 lisa kernel: [   T16]  ret_from_fork+0x20e/0x240
2026-02-19T23:37:50.338976+01:00 lisa kernel: [   T16]  ? kthreads_online_cpu+0x100/0x100
2026-02-19T23:37:50.338978+01:00 lisa kernel: [   T16]  ret_from_fork_asm+0x11/0x20
2026-02-19T23:37:50.338980+01:00 lisa kernel: [   T16]  </TASK>

These seem to be the same type of messages that commit
9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
is supposed to fix.
When I compile a kernel with 9311e6c29b34 as HEAD I do not get these messages, so
I guess I have to do another bisection here.

Bert Karwatzki

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Steven Rostedt]

On Fri, 20 Feb 2026 00:10:41 +0100
Bert Karwatzki <spasswolf@web.de> wrote:

> These seem to be the same type of messages that commit
> 9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
> is supposed to fix.
> When I compile a kernel with 9311e6c29b34 as HEAD I do not get these messages, so
> I guess I have to do another bisection here.

Can you add to the kernel command line:

 trace_event=sched_switch traceoff_after_boot

And then look at /sys/kernel/tracing/trace

It will enable sched_switch event and the traceoff_after_boot will
disable tracing right before running init. That way you can see what is
running during boot that is taking the 90 seconds.

-- Steve

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Donnerstag, dem 19.02.2026 um 19:58 -0500 schrieb Steven Rostedt:
> On Fri, 20 Feb 2026 00:10:41 +0100
> Bert Karwatzki <spasswolf@web.de> wrote:
> 
> > These seem to be the same type of messages that commit
> > 9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
> > is supposed to fix.
> > When I compile a kernel with 9311e6c29b34 as HEAD I do not get these messages, so
> > I guess I have to do another bisection here.
> 
> Can you add to the kernel command line:
> 
>  trace_event=sched_switch traceoff_after_boot
> 
> And then look at /sys/kernel/tracing/trace
> 
> It will enable sched_switch event and the traceoff_after_boot will
> disable tracing right before running init. That way you can see what is
> running during boot that is taking the 90 seconds.
> 
> -- Steve

I think there's a misunderstanding here, the 90s delay happens on shutdown, i.e.
when using either reboot or shutdown. I've changed the subject accordingly.

Bert Karwatzki

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Steven Rostedt]

On Fri, 20 Feb 2026 10:15:43 +0100
Bert Karwatzki <spasswolf@web.de> wrote:

> > It will enable sched_switch event and the traceoff_after_boot will
> > disable tracing right before running init. That way you can see what is
> > running during boot that is taking the 90 seconds.
> > 
> > -- Steve  
> 
> I think there's a misunderstanding here, the 90s delay happens on shutdown, i.e.
> when using either reboot or shutdown. I've changed the subject accordingly.

In that case you should be using the persistent ring buffer ;-)

  https://docs.kernel.org/trace/debugging.html

Add to the kernel command line:

  reserve_mem=20M:2M:trace trace_instance=boot_map@trace

And then before rebooting:

  echo 1 > /sys/kernel/tracing/instances/boot_map/events/sched/sched_switch/enable
  echo 1 > /sys/kernel/tracing/instances/boot_map/tracing_on

Then look at the trace after the reboot:

  cat /sys/kernel/tracing/instances/boot_map/trace

If your laptop doesn't clear memory during a reboot, you should have the trace.

If that's not enough to debug the situation, you can enable other events,
or enable function or function graph tracing. That should all work with the
persistent buffer.

-- Steve

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Freitag, dem 20.02.2026 um 10:44 -0500 schrieb Steven Rostedt:
> On Fri, 20 Feb 2026 10:15:43 +0100
> Bert Karwatzki <spasswolf@web.de> wrote:
> 
> > > It will enable sched_switch event and the traceoff_after_boot will
> > > disable tracing right before running init. That way you can see what is
> > > running during boot that is taking the 90 seconds.
> > > 
> > > -- Steve  
> > 
> > I think there's a misunderstanding here, the 90s delay happens on shutdown, i.e.
> > when using either reboot or shutdown. I've changed the subject accordingly.
> 
> In that case you should be using the persistent ring buffer ;-)
> 
>   https://docs.kernel.org/trace/debugging.html
> 
> Add to the kernel command line:
> 
>   reserve_mem=20M:2M:trace trace_instance=boot_map@trace
> 
> And then before rebooting:
> 
>   echo 1 > /sys/kernel/tracing/instances/boot_map/events/sched/sched_switch/enable
>   echo 1 > /sys/kernel/tracing/instances/boot_map/tracing_on
> 
> Then look at the trace after the reboot:
> 
>   cat /sys/kernel/tracing/instances/boot_map/trace
> 
> If your laptop doesn't clear memory during a reboot, you should have the trace.
> 
> If that's not enough to debug the situation, you can enable other events,
> or enable function or function graph tracing. That should all work with the
> persistent buffer.
> 
> -- Steve

Thank you, I tried this with v6.19 and PREEMPT_RT and got this during a reboot:

# tracer: nop
#
# entries-in-buffer/entries-written: 265126/265126   #P:16
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
           <...>-2657    [013] d..2.    62.492813: sched_switch: prev_comm=bash prev_pid=0xa61 (2657) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=ksoftirqd/13 next_pid=0x86 (134) next_prio=0x78 (120)
           <...>-134     [013] d..2.    62.492817: sched_switch: prev_comm=ksoftirqd/13 prev_pid=0x86 (134) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/13 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [007] d..2.    62.492824: sched_switch: prev_comm=swapper/7 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=xfce4-
terminal next_pid=0x7ca (1994) next_prio=0x78 (120)
           <...>-1994    [007] d..2.    62.493103: sched_switch: prev_comm=xfce4-terminal prev_pid=0x7ca (1994) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/7 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [007] d..2.    62.493135: sched_switch: prev_comm=swapper/7 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=xfce4-
terminal next_pid=0x7ca (1994) next_prio=0x78 (120)
          <idle>-0       [009] d..2.    62.493181: sched_switch: prev_comm=swapper/9 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=gdbus
next_pid=0x7dc (2012) next_prio=0x78 (120)

[...] 


 <...>-22      [000] d..2.   183.258021: sched_switch: prev_comm=migration/0 prev_pid=0x16 (22) prev_prio=0x0 (0) prev_state=0x1 (1) next_comm=swapper/0
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-86      [001] d..2.   183.258037: sched_switch: prev_comm=ksoftirqd/1 prev_pid=0x56 (86) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/1 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [004] d..2.   183.258160: sched_switch: prev_comm=swapper/4 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=systemd-
shutdow next_pid=0x1 (1) next_prio=0x78 (120)
           <...>-1       [004] d..2.   183.258236: sched_switch: prev_comm=systemd-shutdow prev_pid=0x1 (1) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=migration/4 next_pid=0x23 (35) next_prio=0x0 (0)
           <...>-35      [004] d..2.   183.258254: sched_switch: prev_comm=migration/4 prev_pid=0x23 (35) prev_prio=0x0 (0) prev_state=0x1 (1)
next_comm=swapper/4 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [000] d..2.   183.258281: sched_switch: prev_comm=swapper/0 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=systemd-
shutdow next_pid=0x1 (1) next_prio=0x78 (120)

while on v6.19 without PREEMPT_RT I get this

# tracer: nop
#
# entries-in-buffer/entries-written: 32550/32550   #P:16
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
          <idle>-0       [010] d..2.    22.559681: sched_switch: prev_comm=swapper/10 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0)
next_comm=kworker/u64:15 next_pid=0x6e (110) next_prio=0x78 (120)
           <...>-2767    [004] d..2.    22.559687: sched_switch: prev_comm=bash prev_pid=0xacf (2767) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/4 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-110     [010] d..2.    22.559691: sched_switch: prev_comm=kworker/u64:15 prev_pid=0x6e (110) prev_prio=0x78 (120) prev_state=0x80 (128)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [002] d..2.    22.559702: sched_switch: prev_comm=swapper/2 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=xfce4-
terminal next_pid=0x724 (1828) next_prio=0x78 (120)
           <...>-1828    [002] d..2.    22.559951: sched_switch: prev_comm=xfce4-terminal prev_pid=0x724 (1828) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/2 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [008] d..2.    22.560343: sched_switch: prev_comm=swapper/8 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0)
next_comm=rcu_preempt next_pid=0xf (15) next_prio=0x78 (120)
           <...>-15      [008] d..2.    22.560347: sched_switch: prev_comm=rcu_preempt prev_pid=0xf (15) prev_prio=0x78 (120) prev_state=0x80 (128)
next_comm=swapper/8 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [002] d..2.    22.561724: sched_switch: prev_comm=swapper/2 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=xfce4-
terminal next_pid=0x724 (1828) next_prio=0x78 (120)
           <...>-1828    [002] d..2.    22.561822: sched_switch: prev_comm=xfce4-terminal prev_pid=0x724 (1828) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/2 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [008] d..2.    22.561826: sched_switch: prev_comm=swapper/8 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=Xorg
next_pid=0x5cb (1483) next_prio=0x78 (120)

[...]

<...>-252     [006] d..2.    29.512070: sched_switch: prev_comm=kworker/6:2 prev_pid=0xfc (252) prev_prio=0x78 (120) prev_state=0x80 (128) next_comm=swapper/6
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-153     [012] d..2.    29.512074: sched_switch: prev_comm=kworker/12:1 prev_pid=0x99 (153) prev_prio=0x78 (120) prev_state=0x80 (128)
next_comm=swapper/12 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [011] d..2.    29.541390: sched_switch: prev_comm=swapper/11 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0)
next_comm=systemd-shutdow next_pid=0x1 (1) next_prio=0x78 (120)
           <...>-1       [011] d..2.    29.541912: sched_switch: prev_comm=systemd-shutdow prev_pid=0x1 (1) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=migration/11 next_pid=0x51 (81) next_prio=0x0 (0)
           <...>-81      [011] d..2.    29.541933: sched_switch: prev_comm=migration/11 prev_pid=0x51 (81) prev_prio=0x0 (0) prev_state=0x1 (1)
next_comm=swapper/11 next_pid=0x0 (0) next_prio=0x78 (120)
          <idle>-0       [000] d..2.    29.541966: sched_switch: prev_comm=swapper/0 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=systemd-
shutdow next_pid=0x1 (1) next_prio=0x78 (120)
          <idle>-0       [012] d..2.    29.542130: sched_switch: prev_comm=swapper/12 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0)
next_comm=rcu_preempt next_pid=0xf (15) next_prio=0x78 (120)
           <...>-15      [012] d..2.    29.542142: sched_switch: prev_comm=rcu_preempt prev_pid=0xf (15) prev_prio=0x78 (120) prev_state=0x80 (128)
next_comm=swapper/12 next_pid=0x0 (0) next_prio=0x78 (120)

So the time to was is ~120s with PREEMPT_RT and 7s without.

The interesting difference between these two traces is that the second one only
contains messages with "status" d..2. while the first also contains some with different status
(191 of 265126). Could these be the reason for the delay.

$ grep -v d..2. trace.txt

# tracer: nop
#
# entries-in-buffer/entries-written: 265126/265126   #P:16
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||     |         |
           <...>-1584    [011] D..22    62.779670: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [011] D..22    62.779702: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [011] D..22    64.779027: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [011] D..22    64.779052: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1653    [003] D..22    64.810070: sched_switch: prev_comm=Xorg prev_pid=0x675 (1653) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/3 next_pid=0x5c (92) next_prio=0x62 (98)
           <...>-1584    [011] D..22    66.778764: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [011] D..22    66.778786: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-150     [009] D..22    67.793707: sched_switch: prev_comm=kworker/u64:5 prev_pid=0x96 (150) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/9 next_pid=0x74 (116) next_prio=0x62 (98)
           <...>-148     [003] D..22    68.793596: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/3 next_pid=0x5c (92) next_prio=0x62 (98)
           <...>-148     [003] D..22    70.794233: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/3 next_pid=0x5c (92) next_prio=0x62 (98)
           <...>-669     [009] D..21    70.794361: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/9 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-669     [009] D..21    71.214115: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/9 next_pid=0x74 (116) next_prio=0x62 (98)
           <...>-148     [003] D..21    71.794951: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=ktimers/3 next_pid=0x5d (93) next_prio=0x62 (98)
           <...>-148     [003] D..23    71.795947: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/3 next_pid=0x5c (92) next_prio=0x62 (98)
           <...>-148     [012] D..22    75.489983: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/12 next_pid=0x44 (68) next_prio=0x62 (98)
           <...>-1584    [012] D..22    76.776598: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [012] D..22    76.776629: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [012] D..22    78.776540: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-1584    [012] D..22    78.776588: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-671     [010] D..21    78.907165: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=ktimers/10 next_pid=0x3d (61) next_prio=0x62 (98)
           <...>-1372    [012] D..22    80.920002: sched_switch: prev_comm=avahi-daemon prev_pid=0x55c (1372) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-669     [009] D..21    80.935518: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/9 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-669     [009] D..21    80.935533: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/9 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-100     [005] D..21    81.549584: sched_switch: prev_comm=rcuc/5 prev_pid=0x64 (100) prev_prio=0x62 (98) prev_state=0x100 (256)
next_comm=irq/108-amdgpu next_pid=0x1aa (426) next_prio=0x31 (49)
           <...>-148     [012] D..23    81.791530: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/12 next_pid=0x44 (68) next_prio=0x62 (98)
           <...>-671     [004] D..21    82.179446: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/4 next_pid=0x24 (36) next_prio=0x62 (98)
           <...>-150     [002] D..22    83.169248: sched_switch: prev_comm=kworker/u64:5 prev_pid=0x96 (150) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/2 next_pid=0x1c (28) next_prio=0x62 (98)
           <...>-669     [012] D..23    83.247178: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-152     [010] D..21    84.177041: sched_switch: prev_comm=kworker/u64:7 prev_pid=0x98 (152) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/10 next_pid=0x3c (60) next_prio=0x62 (98)
           <...>-159     [006] D..22    84.577962: sched_switch: prev_comm=kworker/u64:14 prev_pid=0x9f (159) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/6 next_pid=0x2c (44) next_prio=0x62 (98)
           <...>-159     [006] D..21    84.579215: sched_switch: prev_comm=kworker/u64:14 prev_pid=0x9f (159) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=irq/110-mt7921e next_pid=0x29c (668) next_prio=0x31 (49)
           <...>-152     [004] D..22    84.789922: sched_switch: prev_comm=kworker/u64:7 prev_pid=0x98 (152) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/4 next_pid=0x24 (36) next_prio=0x62 (98)
           <...>-10      [000] D..21    86.208639: sched_switch: prev_comm=kworker/0:1 prev_pid=0xa (10) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/0 next_pid=0x14 (20) next_prio=0x62 (98)
           <...>-116     [009] D..21    86.254673: sched_switch: prev_comm=rcuc/9 prev_pid=0x74 (116) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=firefox-
esr next_pid=0x7c5 (1989) next_prio=0x62 (98)
           <...>-76      [014] D..23    86.270830: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=irq_work/14 next_pid=0x4a (74) next_prio=0x62 (98)
           <...>-44      [006] D..23    86.270839: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/6:7 next_pid=0xc83 (3203) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270857: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=xdg-
desktop-por next_pid=0x754 (1876) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.270867: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270880: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/14:4 next_pid=0x89e (2206) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.270891: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270903: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=xdg-
desktop-por next_pid=0x754 (1876) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.270911: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270925: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Xorg
next_pid=0x675 (1653) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.270935: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270949: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=xdg-
desktop-por next_pid=0x754 (1876) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.270961: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270971: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Xorg
next_pid=0x675 (1653) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.270981: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.270997: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=xdg-
desktop-por next_pid=0x754 (1876) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.271009: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.271021: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Xorg
next_pid=0x675 (1653) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.271032: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.271043: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=xdg-
desktop-por next_pid=0x754 (1876) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.271062: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.271081: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Xorg
next_pid=0x675 (1653) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.271098: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.271110: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=xdg-
desktop-por next_pid=0x754 (1876) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.271124: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=dbus-
daemon next_pid=0x65d (1629) next_prio=0x78 (120)
           <...>-76      [014] D..23    86.271145: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Xorg
next_pid=0x675 (1653) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274667: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/14:4 next_pid=0x89e (2206) next_prio=0x78 (120)
           <...>-108     [007] D..21    86.274668: sched_switch: prev_comm=rcuc/7 prev_pid=0x6c (108) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/7:4 next_pid=0xd1e (3358) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274678: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/2:2 next_pid=0x161 (353) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274682: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/14:4 next_pid=0x89e (2206) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274687: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/3:1 next_pid=0xe9 (233) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274691: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/2:2 next_pid=0x161 (353) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274695: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/u64:4 next_pid=0x95 (149) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274698: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/3:1 next_pid=0xe9 (233) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274702: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/2 next_pid=0x1e (30) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274705: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/u64:4 next_pid=0x95 (149) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274709: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/3 next_pid=0x5e (94) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274714: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Socket
Thread next_pid=0x96f (2415) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274717: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/u64:4 next_pid=0x95 (149) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274721: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274726: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Socket
Thread next_pid=0x96f (2415) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274730: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/u64:4 next_pid=0x95 (149) next_prio=0x78 (120)
           <...>-140     [015] D..21    86.274732: sched_switch: prev_comm=rcuc/15 prev_pid=0x8c (140) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=systemd
next_pid=0x1 (1) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274735: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274744: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/14 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-140     [015] D..21    86.274747: sched_switch: prev_comm=rcuc/15 prev_pid=0x8c (140) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/15:1 next_pid=0xce (206) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274754: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274761: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/14 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-140     [015] D..21    86.274767: sched_switch: prev_comm=rcuc/15 prev_pid=0x8c (140) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=systemd
next_pid=0x1 (1) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274772: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274775: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Socket
Thread next_pid=0x96f (2415) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274779: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/14 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-140     [015] D..21    86.274787: sched_switch: prev_comm=rcuc/15 prev_pid=0x8c (140) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/15:1 next_pid=0xce (206) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274790: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274795: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Socket
Thread next_pid=0x96f (2415) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274801: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/14 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-140     [015] D..21    86.274804: sched_switch: prev_comm=rcuc/15 prev_pid=0x8c (140) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=systemd
next_pid=0x1 (1) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274812: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274816: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Socket
Thread next_pid=0x96f (2415) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274822: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/14 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-92      [003] D..21    86.274834: sched_switch: prev_comm=rcuc/3 prev_pid=0x5c (92) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/3
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-28      [002] D..21    86.274837: sched_switch: prev_comm=rcuc/2 prev_pid=0x1c (28) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=Socket
Thread next_pid=0x96f (2415) next_prio=0x78 (120)
           <...>-76      [014] D..21    86.274843: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/u64:4 next_pid=0x95 (149) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.276634: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=irq_work/6
next_pid=0x2a (42) next_prio=0x62 (98)
           <...>-60      [010] D..23    86.276634: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/10 next_pid=0x3e (62) next_prio=0x78 (120)
           <...>-44      [006] D..23    86.276657: sched_switch: prev_comm=rcuc/6 prev_pid=0x2c (44) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/6
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276672: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276762: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/4:3 next_pid=0xceb (3307) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276773: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276784: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/4:3 next_pid=0xceb (3307) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276797: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276807: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=WebKitNetworkPr next_pid=0xc68 (3176) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276818: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276833: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276842: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276857: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276867: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276880: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276892: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276903: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=pool-
spawner next_pid=0xbc8 (3016) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276921: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276933: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276948: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276958: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276973: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.276982: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.276996: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277007: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277021: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277031: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=gmain
next_pid=0x8f6 (2294) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277042: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277055: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277066: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277077: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277091: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277101: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277111: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277122: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277130: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277139: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277149: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277158: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277166: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277175: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277184: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277192: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277201: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277210: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277219: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277228: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-60      [010] D..23    86.277239: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/10 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-36      [004] D..23    86.277248: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/4
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-52      [008] D..21    86.308651: sched_switch: prev_comm=rcuc/8 prev_pid=0x34 (52) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/8 next_pid=0x36 (54) next_prio=0x78 (120)
           <...>-68      [012] D..21    86.308652: sched_switch: prev_comm=rcuc/12 prev_pid=0x44 (68) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=systemd-
logind next_pid=0x56c (1388) next_prio=0x78 (120)
           <...>-52      [008] D..21    86.308658: sched_switch: prev_comm=rcuc/8 prev_pid=0x34 (52) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/8:1 next_pid=0xaf (175) next_prio=0x78 (120)
           <...>-20      [000] D..21    86.311699: sched_switch: prev_comm=rcuc/0 prev_pid=0x14 (20) prev_prio=0x62 (98) prev_state=0x100 (256) next_comm=irq/6-
AMDI0010: next_pid=0x159 (345) next_prio=0x31 (49)
           <...>-1535    [000] D..21    86.333765: sched_switch: prev_comm=isc-loop-0001 prev_pid=0x5ff (1535) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/0 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1538    [001] D..21    86.333767: sched_switch: prev_comm=isc-loop-0004 prev_pid=0x602 (1538) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/1 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1541    [007] D..21    86.333768: sched_switch: prev_comm=isc-loop-0005 prev_pid=0x605 (1541) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/7 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1547    [013] D..21    86.333780: sched_switch: prev_comm=isc-loop-0009 prev_pid=0x60b (1547) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/13 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1550    [005] D..21    86.333789: sched_switch: prev_comm=isc-loop-0011 prev_pid=0x60e (1550) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/5 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1517    [009] D..21    86.333796: sched_switch: prev_comm=named prev_pid=0x5ed (1517) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/9 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1549    [003] D..21    86.334055: sched_switch: prev_comm=isc-loop-0010 prev_pid=0x60d (1549) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/3 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-1552    [012] D..21    86.334064: sched_switch: prev_comm=isc-loop-0012 prev_pid=0x610 (1552) prev_prio=0x78 (120) prev_state=0x2 (2)
next_comm=swapper/12 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-124     [011] D..21    86.339629: sched_switch: prev_comm=rcuc/11 prev_pid=0x7c (124) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=named
next_pid=0x5ed (1517) next_prio=0x62 (98)
           <...>-669     [009] D..21    86.384605: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/9 next_pid=0x74 (116) next_prio=0x62 (98)
           <...>-669     [009] D..21    86.422599: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/9 next_pid=0x74 (116) next_prio=0x62 (98)
           <...>-669     [009] D..22    86.435597: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/9 next_pid=0x74 (116) next_prio=0x62 (98)
           <...>-669     [009] D..24    86.599564: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29d (669) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/9 next_pid=0x74 (116) next_prio=0x62 (98)
           <...>-671     [010] D..23    86.642556: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/10 next_pid=0x3c (60) next_prio=0x62 (98)
           <...>-100     [005] D..22    87.291482: sched_switch: prev_comm=rcuc/5 prev_pid=0x64 (100) prev_prio=0x62 (98) prev_state=0x100 (256)
next_comm=irq/108-amdgpu next_pid=0x1aa (426) next_prio=0x31 (49)
           <...>-108     [007] D..21    87.291485: sched_switch: prev_comm=rcuc/7 prev_pid=0x6c (108) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/7
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-100     [005] D..21    87.291494: sched_switch: prev_comm=rcuc/5 prev_pid=0x64 (100) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=swapper/5
next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-100     [005] D..21    87.291513: sched_switch: prev_comm=rcuc/5 prev_pid=0x64 (100) prev_prio=0x62 (98) prev_state=0x100 (256)
next_comm=irq/108-amdgpu next_pid=0x1aa (426) next_prio=0x31 (49)
           <...>-671     [010] D..23    87.871456: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=ktimers/10 next_pid=0x3d (61) next_prio=0x62 (98)
           <...>-68      [012] D..21    88.253434: sched_switch: prev_comm=rcuc/12 prev_pid=0x44 (68) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=irq_work/12 next_pid=0x42 (66) next_prio=0x62 (98)
           <...>-76      [014] D..21    88.253437: sched_switch: prev_comm=rcuc/14 prev_pid=0x4c (76) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=swapper/14 next_pid=0x0 (0) next_prio=0x78 (120)
           <...>-68      [012] D..21    88.253469: sched_switch: prev_comm=rcuc/12 prev_pid=0x44 (68) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/12:4 next_pid=0xa58 (2648) next_prio=0x78 (120)
           <...>-100     [005] D..21    88.253472: sched_switch: prev_comm=rcuc/5 prev_pid=0x64 (100) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/5 next_pid=0x66 (102) next_prio=0x78 (120)
           <...>-116     [009] D..21    88.256459: sched_switch: prev_comm=rcuc/9 prev_pid=0x74 (116) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=kworker/9:1 next_pid=0xb0 (176) next_prio=0x78 (120)
           <...>-100     [005] D..21    88.256462: sched_switch: prev_comm=rcuc/5 prev_pid=0x64 (100) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/5 next_pid=0x66 (102) next_prio=0x78 (120)
           <...>-36      [004] D..21    88.277433: sched_switch: prev_comm=rcuc/4 prev_pid=0x24 (36) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=systemd
next_pid=0x63f (1599) next_prio=0x78 (120)
           <...>-671     [012] D..23    88.383431: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/12 next_pid=0x44 (68) next_prio=0x62 (98)
           <...>-3500    [014] D..22   134.060263: sched_switch: prev_comm=kworker/u64:29 prev_pid=0xdac (3500) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/14 next_pid=0x4c (76) next_prio=0x62 (98)
           <...>-148     [012] D..23   156.035218: sched_switch: prev_comm=kworker/u64:3 prev_pid=0x94 (148) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/12 next_pid=0x44 (68) next_prio=0x62 (98)
           <...>-671     [011] D..23   156.374210: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/11 next_pid=0x7c (124) next_prio=0x62 (98)
           <...>-671     [012] D..22   156.886187: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/12 next_pid=0x44 (68) next_prio=0x62 (98)
           <...>-578     [008] D..21   178.359189: sched_switch: prev_comm=kworker/8:2 prev_pid=0x242 (578) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=kworker/8:1 next_pid=0xaf (175) next_prio=0x78 (120)
           <...>-143     [015] D..21   178.470232: sched_switch: prev_comm=kworker/15:0 prev_pid=0x8f (143) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=kworker/15:1 next_pid=0xce (206) next_prio=0x78 (120)
           <...>-671     [012] D..21   178.523343: sched_switch: prev_comm=napi/phy0-0 prev_pid=0x29f (671) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
           <...>-20      [000] D..21   178.891146: sched_switch: prev_comm=rcuc/0 prev_pid=0x14 (20) prev_prio=0x62 (98) prev_state=0x2 (2)
next_comm=ksoftirqd/0 next_pid=0xe (14) next_prio=0x78 (120)
           <...>-116     [009] D..21   178.938182: sched_switch: prev_comm=rcuc/9 prev_pid=0x74 (116) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=umount
next_pid=0xe27 (3623) next_prio=0x62 (98)
           <...>-116     [009] D..21   178.947159: sched_switch: prev_comm=rcuc/9 prev_pid=0x74 (116) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=umount
next_pid=0xe27 (3623) next_prio=0x62 (98)
           <...>-68      [012] D..21   179.004152: sched_switch: prev_comm=rcuc/12 prev_pid=0x44 (68) prev_prio=0x62 (98) prev_state=0x2 (2) next_comm=umount
next_pid=0xe27 (3623) next_prio=0x62 (98)
           <...>-132     [013] D..21   179.070272: sched_switch: prev_comm=rcuc/13 prev_pid=0x84 (132) prev_prio=0x62 (98) prev_state=0x100 (256)
next_comm=irq/87-nvme0q14 next_pid=0x181 (385) next_prio=0x31 (49)
           <...>-60      [010] D..21   181.208158: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x100 (256)
next_comm=irq/83-nvme0q11 next_pid=0x17b (379) next_prio=0x31 (49)
           <...>-60      [010] D..21   181.321060: sched_switch: prev_comm=rcuc/10 prev_pid=0x3c (60) prev_prio=0x62 (98) prev_state=0x100 (256)
next_comm=irq/83-nvme0q11 next_pid=0x17b (379) next_prio=0x31 (49)
           <...>-1       [002] D..22   182.672954: sched_switch: prev_comm=systemd-shutdow prev_pid=0x1 (1) prev_prio=0x78 (120) prev_state=0x100 (256)
next_comm=rcuc/2 next_pid=0x1c (28) next_prio=0x62 (98)


Bert Karwatzki

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Steven Rostedt]

On Mon, 23 Feb 2026 01:35:36 +0100
Bert Karwatzki <spasswolf@web.de> wrote:

> So the time to was is ~120s with PREEMPT_RT and 7s without.
> 
> The interesting difference between these two traces is that the second one only
> contains messages with "status" d..2. while the first also contains some with different status
> (191 of 265126). Could these be the reason for the delay.
> 
> $ grep -v d..2. trace.txt
> 
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 265126/265126   #P:16
> #
> #                                _-----=> irqs-off/BH-disabled
> #                               / _----=> need-resched
> #                              | / _---=> hardirq/softirq
> #                              || / _--=> preempt-depth
> #                              ||| / _-=> migrate-disable
> #                              |||| /     delay
> #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> #              | |         |   |||||     |         |
>            <...>-1584    [011] D..22    62.779670: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
> next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)

The 'D' means both interrupts 'd' and softirqs 'b' are disabled.

The last number is migrate disable which means the task is pinned to a
CPU. That may be an issue if the system is trying to take down a CPU
and there's a task pinned to it.

Now that we know that the persistent ring buffer works, we can add even
more debugging. We could see where things are stuck...

  cd /sys/kernel/tracing/instances/boot_map
  echo 'stacktrace if prev_state & 3' > events/sched/sched_switch/trigger

That will do a stacktrace at every location that schedules out in a
non-running state. That way we can see what is waiting for something to
finish.

Then in a separate boot, we may want to see where things are pinned.

  echo 'stacktrace if common_flags & 0xf00' > events/sched/sched_switch/trigger

That will do a stacktrace every time a task schedules out with
migration disabled.

-- Steve

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Montag, dem 23.02.2026 um 03:22 -0500 schrieb Steven Rostedt:
> On Mon, 23 Feb 2026 01:35:36 +0100
> Bert Karwatzki <spasswolf@web.de> wrote:
> 
> > So the time to was is ~120s with PREEMPT_RT and 7s without.
> > 
> > The interesting difference between these two traces is that the second one only
> > contains messages with "status" d..2. while the first also contains some with different status
> > (191 of 265126). Could these be the reason for the delay.
> > 
> > $ grep -v d..2. trace.txt
> > 
> > # tracer: nop
> > #
> > # entries-in-buffer/entries-written: 265126/265126   #P:16
> > #
> > #                                _-----=> irqs-off/BH-disabled
> > #                               / _----=> need-resched
> > #                              | / _---=> hardirq/softirq
> > #                              || / _--=> preempt-depth
> > #                              ||| / _-=> migrate-disable
> > #                              |||| /     delay
> > #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> > #              | |         |   |||||     |         |
> >            <...>-1584    [011] D..22    62.779670: sched_switch: prev_comm=ntpd prev_pid=0x630 (1584) prev_prio=0x78 (120) prev_state=0x100 (256)
> > next_comm=mt76-tx phy0 next_pid=0x5fb (1531) next_prio=0x62 (98)
> 
> The 'D' means both interrupts 'd' and softirqs 'b' are disabled.
> 
> The last number is migrate disable which means the task is pinned to a
> CPU. That may be an issue if the system is trying to take down a CPU
> and there's a task pinned to it.
> 
> Now that we know that the persistent ring buffer works, we can add even
> more debugging. We could see where things are stuck...
> 
>   cd /sys/kernel/tracing/instances/boot_map
>   echo 'stacktrace if prev_state & 3' > events/sched/sched_switch/trigger
> 
> That will do a stacktrace at every location that schedules out in a
> non-running state. That way we can see what is waiting for something to
> finish.

I tried that twice and got these results:

Commands:
echo 1 > /sys/kernel/tracing/instances/boot_map/events/sched/sched_switch/enable
echo 'stacktrace if prev_state & 3' > /sys/kernel/tracing/instances/boot_map/events/sched/sched_switch/trigger 
echo 1 > /sys/kernel/tracing/instances/boot_map/tracing_on
reboot

The first time (despite the 265000 entries) the reboot happened at
normals speed, even thought the timestamps suggest something different:
# entries-in-buffer/entries-written: 265170/265170   #P:16
[...]
           <...>-158     [009] d..2.    98.680157: sched_switch: prev_comm=kworker/u64:13 prev_pid=0x9e (158) prev_prio=0x78 (120) prev_state=0x80 (128)
next_comm=swapper/9 next_pid=0x0 (0) next_prio=0x78 (120)
[...]
           <...>-70      [012] d..2.   166.155040: sched_switch: prev_comm=ksoftirqd/12 prev_pid=0x46 (70) prev_prio=0x78 (120) prev_state=0x1 (1)
next_comm=swapper/12 next_pid=0x0 (0) next_prio=0x78 (120)

Here are the messages from /var/log/kern.log that show the last messages of the old kernel
and the first message of the new:
2026-02-23T13:57:38.441240+01:00 lisa kernel: [  T156] amdgpu 0000:03:00.0: [drm] Cannot find any crtc or sizes
2026-02-23T13:58:04.876308+01:00 lisa kernel: [    T0] Linux version 6.19.0-trace (bert@lisa) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU Binutils for Debian)
2.44) #1160 SMP PREEMPT_RT Sat Feb 21 00:22:46 CET 2026

So while the time stamps in the trace suggest that the reboot took at least 68 seconds,
/var/log/kern.log shows that it took only 26s at most. As I observed the whole thing I'm sure
kern.log is correct here.

Then I repeated the process above and this time the shutdown got stuck
again, but the trace was actually shorter:
# entries-in-buffer/entries-written: 195123/195123   #P:16
[...]
          <idle>-0       [002] d..2.   135.554543: sched_switch: prev_comm=swapper/2 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=xfce4-
terminal next_pid=0x7b7 (1975) next_prio=0x78 (120)

[...]
          <idle>-0       [000] d..2.   242.301841: sched_switch: prev_comm=swapper/0 prev_pid=0x0 (0) prev_prio=0x78 (120) prev_state=0x0 (0) next_comm=systemd-
shutdow next_pid=0x1 (1) next_prio=0x78 (120)

These are the line from kern.log that show the longer delay:
2026-02-23T13:59:19.348451+01:00 lisa kernel: [  T146] amdgpu 0000:03:00.0: [drm] Cannot find any crtc or sizes
2026-02-23T14:02:13.817354+01:00 lisa kernel: [    T0] Linux version 6.19.0-trace (bert@lisa) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU Binutils for Debian)
2.44) #1160 SMP PREEMPT_RT Sat Feb 21 00:22:46 CET 2026

So this time we have a trace that took about 107s and also a longer delay in kern.log.
The kern.log delay here is not the time it took for the reboot though, as the there might
have been a delay between the last log message of the old kernel and the reboot command.

From now on I'll reboot like this to get a proper timestamp in /var/log/kern.log:
# echo reboot > /dev/kmsg && reboot

Bert Karwatzki

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

As the bisection in suggested that commit9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
is somehow causing the problem I put some printk()s in the code changed by this
commit and captured the output via netconsole (I tried using trace_printk() to
use the persistent ringbuffer but got no output).

This is the debug patch (for v6.19):

commit 655ad0d7ce2d03b1b8bfbc2a3e6c36b46a4604c5
Author: Bert Karwatzki <spasswolf@web.de>
Date:   Mon Feb 23 21:49:47 2026 +0100

    cgroup: add printk() cgroup_task_dead for PREEMPT_RT
    
    Signed-off-by: Bert Karwatzki <spasswolf@web.de>

diff --git a/kernel/cgroup/cgroup.c b/kernel/cgroup/cgroup.c
index 5f0d33b04910..16bb40df5dd0 100644
--- a/kernel/cgroup/cgroup.c
+++ b/kernel/cgroup/cgroup.c
@@ -7029,6 +7029,7 @@ static void cgrp_dead_tasks_iwork_fn(struct irq_work *iwork)
 {
 	struct llist_node *lnode;
 	struct task_struct *task, *next;
+	printk(KERN_INFO "%s:\n", __func__);
 
 	lnode = llist_del_all(this_cpu_ptr(&cgrp_dead_tasks));
 	llist_for_each_entry_safe(task, next, lnode, cg_dead_lnode) {
@@ -7050,6 +7051,7 @@ static void __init cgroup_rt_init(void)
 
 void cgroup_task_dead(struct task_struct *task)
 {
+	printk(KERN_INFO "%s: task = %s\n", __func__, task->comm);
 	get_task_struct(task);
 	llist_add(&task->cg_dead_lnode, this_cpu_ptr(&cgrp_dead_tasks));
 	irq_work_queue(this_cpu_ptr(&cgrp_dead_tasks_iwork));


This is the output captured via netconsole after rebooting via
# echo reboot > /dev/kmsg && reboot

2026-02-24T00:17:38.836655+01:00 localhost 12,5335,211298089,-,caller=T3211;reboot 
2026-02-24T00:17:38.848658+01:00 localhost 6,5336,211309667,-,caller=T0;cgroup_task_dead: task = reboot
2026-02-24T00:17:38.848658+01:00 localhost 6,5337,211310223,-,caller=T50;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:17:38.852694+01:00 localhost 6,5338,211313770,-,caller=T0;cgroup_task_dead: task = gmain
2026-02-24T00:17:38.852694+01:00 localhost 6,5339,211313776,-,caller=T0;cgroup_task_dead: task = xfce4-sess:cs0
2026-02-24T00:17:38.852694+01:00 localhost 6,5340,211313798,-,caller=T0;cgroup_task_dead: task = xfce4-sess:sh0
2026-02-24T00:17:38.852694+01:00 localhost 6,5341,211313810,-,caller=T0;cgroup_task_dead: task = xfce4-:sh_opt0
2026-02-24T00:17:38.852694+01:00 localhost 6,5342,211313830,-,caller=T0;cgroup_task_dead: task = xfce4-:traceq0
2026-02-24T00:17:38.852694+01:00 localhost 6,5343,211313840,-,caller=T0;cgroup_task_dead: task = pool-spawner
2026-02-24T00:17:38.852694+01:00 localhost 6,5344,211313839,-,caller=T0;cgroup_task_dead: task = xfce4-:traceq0
2026-02-24T00:17:38.852694+01:00 localhost 6,5345,211313868,-,caller=T0;cgroup_task_dead: task = xfce4-session
2026-02-24T00:17:38.852694+01:00 localhost 6,5346,211313871,-,caller=T0;cgroup_task_dead: task = xfce4-:traceq0
2026-02-24T00:17:38.852694+01:00 localhost 6,5347,211313874,-,caller=T0;cgroup_task_dead: task = xfce4-s:disk$0
[...]
Here comes the part which shows the delay (I did not remove any message here):
2026-02-24T00:17:40.964180+01:00 localhost 6,6838,213423568,-,caller=T0;cgroup_task_dead: task = (sd-close)
2026-02-24T00:17:40.964244+01:00 localhost 6,6839,213423756,-,caller=T0;cgroup_task_dead: task = systemctl
2026-02-24T00:17:40.964576+01:00 localhost 6,6840,213424221,-,caller=T34;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:17:40.964649+01:00 localhost 6,6841,213424221,-,caller=T23;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:17:40.964969+01:00 localhost 6,6842,213424435,-,caller=T0;cgroup_task_dead: task = (sd-close)
2026-02-24T00:17:40.965057+01:00 localhost 6,6843,213425219,-,caller=T50;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:17:44.025094+01:00 localhost 6,6844,216485806,-,caller=T0;cgroup_task_dead: task = (udev-worker)
2026-02-24T00:17:44.025094+01:00 localhost 6,6845,216485810,-,caller=T0;cgroup_task_dead: task = (udev-worker)
2026-02-24T00:17:44.025387+01:00 localhost 6,6846,216485816,-,caller=T0;cgroup_task_dead: task = (udev-worker)
2026-02-24T00:17:44.025642+01:00 localhost 6,6847,216486228,-,caller=T66;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:17:44.025718+01:00 localhost 6,6848,216486239,-,caller=T122;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:17:44.025923+01:00 localhost 6,6849,216486239,-,caller=T82;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:19:11.070444+01:00 localhost 6,6850,303512419,-,caller=T0;cgroup_task_dead: task = systemd
2026-02-24T00:19:11.070444+01:00 localhost 6,6851,303513238,-,caller=T34;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:19:11.070725+01:00 localhost 6,6852,303513728,-,caller=T0;cgroup_task_dead: task = (sd-pam)
2026-02-24T00:19:11.070888+01:00 localhost 6,6853,303514010,-,caller=T0;cgroup_task_dead: task = (sd-close)
2026-02-24T00:19:11.071192+01:00 localhost 6,6854,303514221,-,caller=T90;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:19:11.071291+01:00 localhost 6,6855,303514238,-,caller=T50;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:19:11.071626+01:00 localhost 6,6856,303514629,-,caller=T0;cgroup_task_dead: task = (sd-close)
2026-02-24T00:19:11.072139+01:00 localhost 6,6857,303515237,-,caller=T50;cgrp_dead_tasks_iwork_fn: 
2026-02-24T00:19:11.107473+01:00 localhost 6,6858,303549400,-,caller=T0;cgroup_task_dead: task = psimon
2026-02-24T00:19:11.107473+01:00 localhost 6,6859,303550244,-,caller=T66;cgrp_dead_tasks_iwork_fn:
[...]

I've tried this several times and the function calls just before the delay are always the same.

Bert Karwatzki

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

I've done some more monitoring with this debug patch which monitors
cgroup_task_dead() and the function which calls it finish task switch.
To avoid too many messages some printk()s are filtered by command name
(a previous patch showed systemd to be the problematic process):

diff --git a/kernel/cgroup/cgroup.c b/kernel/cgroup/cgroup.c
index 5f0d33b04910..7bb6931a4d86 100644
--- a/kernel/cgroup/cgroup.c
+++ b/kernel/cgroup/cgroup.c
@@ -6990,25 +6990,32 @@ static void do_cgroup_task_dead(struct task_struct *tsk)
 {
 	struct css_set *cset;
 	unsigned long flags;
+	printk(KERN_INFO "%s 0: task = %px\n", __func__, tsk);
 
 	spin_lock_irqsave(&css_set_lock, flags);
 
+	printk(KERN_INFO "%s 1: task = %px\n", __func__, tsk);
 	WARN_ON_ONCE(list_empty(&tsk->cg_list));
 	cset = task_css_set(tsk);
+	printk(KERN_INFO "%s 2: task = %px\n", __func__, tsk);
 	css_set_move_task(tsk, cset, NULL, false);
+	printk(KERN_INFO "%s 3: task = %px\n", __func__, tsk);
 	cset->nr_tasks--;
 	/* matches the signal->live check in css_task_iter_advance() */
 	if (thread_group_leader(tsk) && atomic_read(&tsk->signal->live))
 		list_add_tail(&tsk->cg_list, &cset->dying_tasks);
 
+	printk(KERN_INFO "%s 4: task = %px\n", __func__, tsk);
 	if (dl_task(tsk))
 		dec_dl_tasks_cs(tsk);
 
+	printk(KERN_INFO "%s 5: task = %px\n", __func__, tsk);
 	WARN_ON_ONCE(cgroup_task_frozen(tsk));
 	if (unlikely(!(tsk->flags & PF_KTHREAD) &&
 		     test_bit(CGRP_FREEZE, &task_dfl_cgroup(tsk)->flags)))
 		cgroup_update_frozen(task_dfl_cgroup(tsk));
 
+	printk(KERN_INFO "%s 6: task = %px\n", __func__, tsk);
 	spin_unlock_irqrestore(&css_set_lock, flags);
 }
 
@@ -7029,9 +7036,11 @@ static void cgrp_dead_tasks_iwork_fn(struct irq_work *iwork)
 {
 	struct llist_node *lnode;
 	struct task_struct *task, *next;
+	printk(KERN_INFO "%s:\n", __func__);
 
 	lnode = llist_del_all(this_cpu_ptr(&cgrp_dead_tasks));
 	llist_for_each_entry_safe(task, next, lnode, cg_dead_lnode) {
+		printk(KERN_INFO "%s: %px %s", __func__, task, task->comm);
 		do_cgroup_task_dead(task);
 		put_task_struct(task);
 	}
@@ -7050,6 +7059,7 @@ static void __init cgroup_rt_init(void)
 
 void cgroup_task_dead(struct task_struct *task)
 {
+	printk(KERN_INFO "%s: task = %px (%s)\n", __func__, task, task->comm);
 	get_task_struct(task);
 	llist_add(&task->cg_dead_lnode, this_cpu_ptr(&cgrp_dead_tasks));
 	irq_work_queue(this_cpu_ptr(&cgrp_dead_tasks_iwork));
@@ -7059,6 +7069,7 @@ static void __init cgroup_rt_init(void) {}
 
 void cgroup_task_dead(struct task_struct *task)
 {
+	printk(KERN_INFO "%s: task = %px (%s)\n", __func__, task, task->comm);
 	do_cgroup_task_dead(task);
 }
 #endif	/* CONFIG_PREEMPT_RT */
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 854984967fe2..73e477d8cf1a 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -5078,6 +5078,8 @@ static struct rq *finish_task_switch(struct task_struct *prev)
 	struct rq *rq = this_rq();
 	struct mm_struct *mm = rq->prev_mm;
 	unsigned int prev_state;
+	if (!strcmp(prev->comm, "systemd"))
+		printk(KERN_INFO "%s 0: %px\n", __func__, prev);
 
 	/*
 	 * The previous task will have left us with a preempt_count of 2
@@ -5144,15 +5146,18 @@ static struct rq *finish_task_switch(struct task_struct *prev)
 	}
 
 	if (unlikely(prev_state == TASK_DEAD)) {
+		printk(KERN_INFO "%s 1: %px (%s)\n", __func__, prev, prev->comm);
 		if (prev->sched_class->task_dead)
 			prev->sched_class->task_dead(prev);
 
+		printk(KERN_INFO "%s 2: %px (%s)\n", __func__, prev, prev->comm);
 		/*
 		 * sched_ext_dead() must come before cgroup_task_dead() to
 		 * prevent cgroups from being removed while its member tasks are
 		 * visible to SCX schedulers.
 		 */
 		sched_ext_dead(prev);
+		printk(KERN_INFO "%s 3: %px (%s)\n", __func__, prev, prev->comm);
 		cgroup_task_dead(prev);
 
 		/* Task is done with its stack. */
@@ -5202,6 +5207,8 @@ static __always_inline struct rq *
 context_switch(struct rq *rq, struct task_struct *prev,
 	       struct task_struct *next, struct rq_flags *rf)
 {
+	if (!strcmp(prev->comm, "systemd"))
+		printk(KERN_INFO "%s 0: %px\n", __func__, prev);
 	prepare_task_switch(rq, prev, next);
 
 	/*


I also tried monitoring the schedule_tail(), which is one of the two function calling
finish_task_switch(), but that did get rid of the delay.

The result from this is:
2026-02-24T13:13:21.739185+01:00 localhost 12,32039,34364889,-,caller=T2955;reboot 
[...]
Here the delay section begins (all message here have comm == "systemd"):
2026-02-24T13:13:38.124013+01:00 localhost 6,45456,50748843,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:13:38.124234+01:00 localhost 6,45457,50748851,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:13:38.271984+01:00 localhost 6,45458,50896237,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:13:38.272255+01:00 localhost 6,45459,50896244,-,caller=T52;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:13:38.272556+01:00 localhost 6,45460,50896287,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:13:38.272759+01:00 localhost 6,45461,50896289,-,caller=T51;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:13:38.273225+01:00 localhost 6,45462,50896303,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:13:38.273406+01:00 localhost 6,45463,50896305,-,caller=T51;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:13:38.273819+01:00 localhost 6,45464,50896481,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:13:38.274025+01:00 localhost 6,45465,50896484,-,caller=T0;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:13:38.274465+01:00 localhost 6,45466,50896801,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:13:38.274635+01:00 localhost 6,45467,50896804,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:13:38.275034+01:00 localhost 6,45468,50897328,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:13:38.275254+01:00 localhost 6,45469,50897331,-,caller=T2077;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:13:38.275680+01:00 localhost 6,45470,50897600,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:13:38.275886+01:00 localhost 6,45471,50897602,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:13:38.276300+01:00 localhost 6,45472,50897936,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:13:38.276487+01:00 localhost 6,45473,50897939,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:13:38.276907+01:00 localhost 6,45474,50898225,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:13:38.279144+01:00 localhost 6,45475,50898228,-,caller=T68;finish_task_switch 0: ffff97fd40884300

[...] 1505 similar lines removed

2026-02-24T13:14:54.000427+01:00 localhost 6,46981,126614226,-,caller=T44;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:14:54.000967+01:00 localhost 6,46982,126614420,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:14:54.001060+01:00 localhost 6,46983,126614422,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:14:54.001562+01:00 localhost 6,46984,126614462,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:14:54.001666+01:00 localhost 6,46985,126614463,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:14:54.002182+01:00 localhost 6,46986,126614533,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:14:54.002296+01:00 localhost 6,46987,126614534,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:14:54.002811+01:00 localhost 6,46988,126615219,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:14:54.002910+01:00 localhost 6,46989,126615221,-,caller=T42;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:14:54.003402+01:00 localhost 6,46990,126616376,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:14:54.003510+01:00 localhost 6,46991,126616378,-,caller=T0;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:14:54.004034+01:00 localhost 6,46992,126621884,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:14:54.004125+01:00 localhost 6,46993,126621887,-,caller=T0;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:14:54.004645+01:00 localhost 6,46994,126625311,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:14:54.004734+01:00 localhost 6,46995,126625314,-,caller=T235;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:14:54.013405+01:00 localhost 6,46996,126637601,-,caller=T1;context_switch 0: ffff97fd40884300
2026-02-24T13:14:54.013614+01:00 localhost 6,46997,126637603,-,caller=T0;finish_task_switch 0: ffff97fd40884300
2026-02-24T13:14:54.014165+01:00 localhost 6,46998,126638229,-,caller=T1573;context_switch 0: ffff97fd46050000
2026-02-24T13:14:54.014266+01:00 localhost 6,46999,126638232,-,caller=T44;finish_task_switch 0: ffff97fd46050000
2026-02-24T13:14:54.014774+01:00 localhost 6,47000,126638469,-,caller=T1573;context_switch 0: ffff97fd46050000 END

So there's something strange going on here with the scheduler.


Bert Karwatzki

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Dienstag, dem 24.02.2026 um 13:44 +0100 schrieb Bert Karwatzki:
> I've done some more monitoring with this debug patch which monitors
> cgroup_task_dead() and the function which calls it finish task switch.
> To avoid too many messages some printk()s are filtered by command name
> (a previous patch showed systemd to be the problematic process):
> 
> diff --git a/kernel/cgroup/cgroup.c b/kernel/cgroup/cgroup.c
> index 5f0d33b04910..7bb6931a4d86 100644
> --- a/kernel/cgroup/cgroup.c
> +++ b/kernel/cgroup/cgroup.c
> @@ -6990,25 +6990,32 @@ static void do_cgroup_task_dead(struct task_struct *tsk)
>  {
>  	struct css_set *cset;
>  	unsigned long flags;
> +	printk(KERN_INFO "%s 0: task = %px\n", __func__, tsk);
>  
>  	spin_lock_irqsave(&css_set_lock, flags);
>  
> +	printk(KERN_INFO "%s 1: task = %px\n", __func__, tsk);
>  	WARN_ON_ONCE(list_empty(&tsk->cg_list));
>  	cset = task_css_set(tsk);
> +	printk(KERN_INFO "%s 2: task = %px\n", __func__, tsk);
>  	css_set_move_task(tsk, cset, NULL, false);
> +	printk(KERN_INFO "%s 3: task = %px\n", __func__, tsk);
>  	cset->nr_tasks--;
>  	/* matches the signal->live check in css_task_iter_advance() */
>  	if (thread_group_leader(tsk) && atomic_read(&tsk->signal->live))
>  		list_add_tail(&tsk->cg_list, &cset->dying_tasks);
>  
> +	printk(KERN_INFO "%s 4: task = %px\n", __func__, tsk);
>  	if (dl_task(tsk))
>  		dec_dl_tasks_cs(tsk);
>  
> +	printk(KERN_INFO "%s 5: task = %px\n", __func__, tsk);
>  	WARN_ON_ONCE(cgroup_task_frozen(tsk));
>  	if (unlikely(!(tsk->flags & PF_KTHREAD) &&
>  		     test_bit(CGRP_FREEZE, &task_dfl_cgroup(tsk)->flags)))
>  		cgroup_update_frozen(task_dfl_cgroup(tsk));
>  
> +	printk(KERN_INFO "%s 6: task = %px\n", __func__, tsk);
>  	spin_unlock_irqrestore(&css_set_lock, flags);
>  }
>  
> @@ -7029,9 +7036,11 @@ static void cgrp_dead_tasks_iwork_fn(struct irq_work *iwork)
>  {
>  	struct llist_node *lnode;
>  	struct task_struct *task, *next;
> +	printk(KERN_INFO "%s:\n", __func__);
>  
>  	lnode = llist_del_all(this_cpu_ptr(&cgrp_dead_tasks));
>  	llist_for_each_entry_safe(task, next, lnode, cg_dead_lnode) {
> +		printk(KERN_INFO "%s: %px %s", __func__, task, task->comm);
>  		do_cgroup_task_dead(task);
>  		put_task_struct(task);
>  	}
> @@ -7050,6 +7059,7 @@ static void __init cgroup_rt_init(void)
>  
>  void cgroup_task_dead(struct task_struct *task)
>  {
> +	printk(KERN_INFO "%s: task = %px (%s)\n", __func__, task, task->comm);
>  	get_task_struct(task);
>  	llist_add(&task->cg_dead_lnode, this_cpu_ptr(&cgrp_dead_tasks));
>  	irq_work_queue(this_cpu_ptr(&cgrp_dead_tasks_iwork));
> @@ -7059,6 +7069,7 @@ static void __init cgroup_rt_init(void) {}
>  
>  void cgroup_task_dead(struct task_struct *task)
>  {
> +	printk(KERN_INFO "%s: task = %px (%s)\n", __func__, task, task->comm);
>  	do_cgroup_task_dead(task);
>  }
>  #endif	/* CONFIG_PREEMPT_RT */
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c
> index 854984967fe2..73e477d8cf1a 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -5078,6 +5078,8 @@ static struct rq *finish_task_switch(struct task_struct *prev)
>  	struct rq *rq = this_rq();
>  	struct mm_struct *mm = rq->prev_mm;
>  	unsigned int prev_state;
> +	if (!strcmp(prev->comm, "systemd"))
> +		printk(KERN_INFO "%s 0: %px\n", __func__, prev);
>  
>  	/*
>  	 * The previous task will have left us with a preempt_count of 2
> @@ -5144,15 +5146,18 @@ static struct rq *finish_task_switch(struct task_struct *prev)
>  	}
>  
>  	if (unlikely(prev_state == TASK_DEAD)) {
> +		printk(KERN_INFO "%s 1: %px (%s)\n", __func__, prev, prev->comm);
>  		if (prev->sched_class->task_dead)
>  			prev->sched_class->task_dead(prev);
>  
> +		printk(KERN_INFO "%s 2: %px (%s)\n", __func__, prev, prev->comm);
>  		/*
>  		 * sched_ext_dead() must come before cgroup_task_dead() to
>  		 * prevent cgroups from being removed while its member tasks are
>  		 * visible to SCX schedulers.
>  		 */
>  		sched_ext_dead(prev);
> +		printk(KERN_INFO "%s 3: %px (%s)\n", __func__, prev, prev->comm);
>  		cgroup_task_dead(prev);
>  
>  		/* Task is done with its stack. */
> @@ -5202,6 +5207,8 @@ static __always_inline struct rq *
>  context_switch(struct rq *rq, struct task_struct *prev,
>  	       struct task_struct *next, struct rq_flags *rf)
>  {
> +	if (!strcmp(prev->comm, "systemd"))
> +		printk(KERN_INFO "%s 0: %px\n", __func__, prev);
>  	prepare_task_switch(rq, prev, next);
>  
>  	/*
> 
> 
> I also tried monitoring the schedule_tail(), which is one of the two function calling
> finish_task_switch(), but that did get rid of the delay.

This is incorrect. Monitoring schedule_tail() does not undo the delayed shutdown, but
the delay probalbly has only 95% reproducability.

> 
> The result from this is:
> 2026-02-24T13:13:21.739185+01:00 localhost 12,32039,34364889,-,caller=T2955;reboot 
> [...]
> Here the delay section begins (all message here have comm == "systemd"):
> 2026-02-24T13:13:38.124013+01:00 localhost 6,45456,50748843,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.124234+01:00 localhost 6,45457,50748851,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.271984+01:00 localhost 6,45458,50896237,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.272255+01:00 localhost 6,45459,50896244,-,caller=T52;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.272556+01:00 localhost 6,45460,50896287,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.272759+01:00 localhost 6,45461,50896289,-,caller=T51;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.273225+01:00 localhost 6,45462,50896303,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.273406+01:00 localhost 6,45463,50896305,-,caller=T51;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.273819+01:00 localhost 6,45464,50896481,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.274025+01:00 localhost 6,45465,50896484,-,caller=T0;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:13:38.274465+01:00 localhost 6,45466,50896801,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.274635+01:00 localhost 6,45467,50896804,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.275034+01:00 localhost 6,45468,50897328,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.275254+01:00 localhost 6,45469,50897331,-,caller=T2077;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.275680+01:00 localhost 6,45470,50897600,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.275886+01:00 localhost 6,45471,50897602,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.276300+01:00 localhost 6,45472,50897936,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.276487+01:00 localhost 6,45473,50897939,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.276907+01:00 localhost 6,45474,50898225,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:13:38.279144+01:00 localhost 6,45475,50898228,-,caller=T68;finish_task_switch 0: ffff97fd40884300
> 
> [...] 1505 similar lines removed
> 
> 2026-02-24T13:14:54.000427+01:00 localhost 6,46981,126614226,-,caller=T44;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.000967+01:00 localhost 6,46982,126614420,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.001060+01:00 localhost 6,46983,126614422,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.001562+01:00 localhost 6,46984,126614462,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.001666+01:00 localhost 6,46985,126614463,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.002182+01:00 localhost 6,46986,126614533,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.002296+01:00 localhost 6,46987,126614534,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.002811+01:00 localhost 6,46988,126615219,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.002910+01:00 localhost 6,46989,126615221,-,caller=T42;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.003402+01:00 localhost 6,46990,126616376,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.003510+01:00 localhost 6,46991,126616378,-,caller=T0;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.004034+01:00 localhost 6,46992,126621884,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.004125+01:00 localhost 6,46993,126621887,-,caller=T0;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.004645+01:00 localhost 6,46994,126625311,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.004734+01:00 localhost 6,46995,126625314,-,caller=T235;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.013405+01:00 localhost 6,46996,126637601,-,caller=T1;context_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.013614+01:00 localhost 6,46997,126637603,-,caller=T0;finish_task_switch 0: ffff97fd40884300
> 2026-02-24T13:14:54.014165+01:00 localhost 6,46998,126638229,-,caller=T1573;context_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.014266+01:00 localhost 6,46999,126638232,-,caller=T44;finish_task_switch 0: ffff97fd46050000
> 2026-02-24T13:14:54.014774+01:00 localhost 6,47000,126638469,-,caller=T1573;context_switch 0: ffff97fd46050000 END
> 
> So there's something strange going on here with the scheduler.
> 
> 
> Bert Karwatzki

Re: ~90s shutdown delay with v6.19 and PREEMPT_RT

[Steven Rostedt]

On Tue, 24 Feb 2026 00:36:27 +0100
Bert Karwatzki <spasswolf@web.de> wrote:

> As the bisection in suggested that commit9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
> is somehow causing the problem I put some printk()s in the code changed by this
> commit and captured the output via netconsole (I tried using trace_printk() to
> use the persistent ringbuffer but got no output).

It's described in the document I posted:

   https://docs.kernel.org/trace/debugging.html

    Using trace_printk() in the boot instance

    By default, the content of trace_printk() goes into the top level
    tracing instance. But this instance is never preserved across
    boots. To have the trace_printk() content, and some other internal
    tracing go to the preserved buffer (like dump stacks), either set
    the instance to be the trace_printk() destination from the kernel
    command line, or set it after boot up via the trace_printk_dest
    option.

    After boot up:

    echo 1 > /sys/kernel/tracing/instances/boot_map/options/trace_printk_dest

    From the kernel command line:

    reserve_mem=12M:4096:trace trace_instance=boot_map^traceprintk^traceoff@trace

    If setting it from the kernel command line, it is recommended to
    also disable tracing with the “traceoff” flag, and enable tracing
    after boot up. Otherwise the trace from the most recent boot will
    be mixed with the trace from the previous boot, and may make it
    confusing to read.

-- Steve

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-20 00:10:41 [+0100], Bert Karwatzki wrote:
>  BUG: sleeping function called from invalid context at kernel/printk/printk.c:3377
>  in_atomic(): 0, irqs_disabled(): 0, non_block: 0, pid: 16, name: pr/legacy
…
>   <TASK>
>   dump_stack_lvl+0x4b/0x70
>   __might_resched.cold+0xaf/0xbd
>   console_conditional_schedule+0x26/0x30
…
This is addressed by commit 8e9bf8b9e8c0a ("printk, vt, fbcon: Remove
console_conditional_schedule()")

Sebastian

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-19 17:46:47 [+0100], Bert Karwatzki wrote:
> Since linux v6.19 I noticed that rebooting my MSI Alpha 15 Laptop
> would hang for about ~90s before rebooting. I bisected this (from
> v6.18 to v6.19) and got this as the first bad commit:
> 9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
…

I'm on it. I looks like we free the task after sched_process_wait() but
before it is entirely gone there is a wait() on its pid. Some of them do
come back but one seems to be stuck and I need to figure out which one.
If we get rid of the LAZY then it happens "quick" enough so it works.

> Bert Karwatzki

Sebastian

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Mittwoch, dem 25.02.2026 um 16:43 +0100 schrieb Sebastian Andrzej Siewior:
> On 2026-02-19 17:46:47 [+0100], Bert Karwatzki wrote:
> > Since linux v6.19 I noticed that rebooting my MSI Alpha 15 Laptop
> > would hang for about ~90s before rebooting. I bisected this (from
> > v6.18 to v6.19) and got this as the first bad commit:
> > 9311e6c29b34 ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT")
> …
> 
> I'm on it. I looks like we free the task after sched_process_wait() but
> before it is entirely gone there is a wait() on its pid. Some of them do
> come back but one seems to be stuck and I need to figure out which one.
> If we get rid of the LAZY then it happens "quick" enough so it works.
> 
> > Bert Karwatzki
> 
> Sebastian

I've done two testruns with this debug patch (The persistant log buffer works now, thanks
again to Steven Rostedt):

diff --git a/kernel/cgroup/cgroup.c b/kernel/cgroup/cgroup.c
index 5f0d33b04910..b750aa284b89 100644
--- a/kernel/cgroup/cgroup.c
+++ b/kernel/cgroup/cgroup.c
@@ -6990,6 +6990,7 @@ static void do_cgroup_task_dead(struct task_struct *tsk)
 {
 	struct css_set *cset;
 	unsigned long flags;
+	trace_printk(KERN_INFO "%s 0: task = %px\n", __func__, tsk);
 
 	spin_lock_irqsave(&css_set_lock, flags);
 
@@ -7029,9 +7030,11 @@ static void cgrp_dead_tasks_iwork_fn(struct irq_work *iwork)
 {
 	struct llist_node *lnode;
 	struct task_struct *task, *next;
+	trace_printk(KERN_INFO "%s:\n", __func__);
 
 	lnode = llist_del_all(this_cpu_ptr(&cgrp_dead_tasks));
 	llist_for_each_entry_safe(task, next, lnode, cg_dead_lnode) {
+		trace_printk(KERN_INFO "%s: %px %s", __func__, task, task->comm);
 		do_cgroup_task_dead(task);
 		put_task_struct(task);
 	}
@@ -7050,6 +7053,7 @@ static void __init cgroup_rt_init(void)
 
 void cgroup_task_dead(struct task_struct *task)
 {
+	trace_printk(KERN_INFO "%s: task = %px (%s)\n", __func__, task, task->comm);
 	get_task_struct(task);
 	llist_add(&task->cg_dead_lnode, this_cpu_ptr(&cgrp_dead_tasks));
 	irq_work_queue(this_cpu_ptr(&cgrp_dead_tasks_iwork));
@@ -7059,6 +7063,7 @@ static void __init cgroup_rt_init(void) {}
 
 void cgroup_task_dead(struct task_struct *task)
 {
+	trace_printk(KERN_INFO "%s: task = %px (%s)\n", __func__, task, task->comm);
 	do_cgroup_task_dead(task);
 }
 #endif	/* CONFIG_PREEMPT_RT */
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 854984967fe2..19b130b831bc 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -5078,6 +5078,7 @@ static struct rq *finish_task_switch(struct task_struct *prev)
 	struct rq *rq = this_rq();
 	struct mm_struct *mm = rq->prev_mm;
 	unsigned int prev_state;
+	trace_printk(KERN_INFO "%s 0: %px (%s)\n", __func__, prev, prev->comm);
 
 	/*
 	 * The previous task will have left us with a preempt_count of 2
@@ -5153,6 +5154,7 @@ static struct rq *finish_task_switch(struct task_struct *prev)
 		 * visible to SCX schedulers.
 		 */
 		sched_ext_dead(prev);
+		trace_printk(KERN_INFO "%s 1: %px (%s)\n", __func__, prev, prev->comm);
 		cgroup_task_dead(prev);
 
 		/* Task is done with its stack. */
@@ -5202,6 +5204,7 @@ static __always_inline struct rq *
 context_switch(struct rq *rq, struct task_struct *prev,
 	       struct task_struct *next, struct rq_flags *rf)
 {
+	trace_printk(KERN_INFO "%s 0: %px (%s)\n", __func__, prev, prev->comm);
 	prepare_task_switch(rq, prev, next);
 
 	/*


This if from PREEMPT_RT log, there*s a long pause in which cgroup_task_dead() is not called
59366:           <...>-3209    [001] d..2.    33.110392: 0xffffffffa36c309b: 6context_switch 0: ffff933eb264a180 (reboot)
[...]
112455:          <idle>-0       [006] ...1.    40.503766: 0xffffffffa2da570c: 6cgroup_task_dead: task = ffff933f1885c300 ((udev-worker))
[...] no call to cgroup_task_dead() here, just finish_task_switch() and context_switch()
217571:          <idle>-0       [010] ...1.   125.282118: 0xffffffffa2da570c: 6cgroup_task_dead: task = ffff933e94fae480 (systemd)
[...]
274103          <idle>-0       [014] d..2.   130.157472: 0xffffffffa2cef125: 6finish_task_switch 0: ffff933e815e10c0 (ksoftirqd/14)


This is other log (no pause here, just the first messages after reboot is initiated and
the last message, to show duration of shutdown):

58029:           <...>-2975    [003] d..2.    33.564291: 0xffffffff934b3e89: 6context_switch 0: ffff88e1e0302180 (reboot)
[...]
107700           <...>-1       [000] d..2.    37.352191: 0xffffffff92aee9c5: 6finish_task_switch 0: ffffffff93c12980 (swapper/0)

The complete logs are here:
https://gitlab.freedesktop.org/spasswolf/pastebin/-/issues/2

Bert Karwatzki

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-25 17:37:56 [+0100], Bert Karwatzki wrote:
> I've done two testruns with this debug patch (The persistant log buffer works now, thanks
> again to Steven Rostedt):

…
> This if from PREEMPT_RT log, there*s a long pause in which cgroup_task_dead() is not called

Yeah, I don't know why. The irq-work is invoked slightly delayed so that
part is working.

| irq_work-24        0..... 1501734us : cgrp_dead_tasks_iwork_fn: Kill ffff888101588000 (sd-close)-1964
| systemd--1         1..... 1502194us : sched_process_wait: comm=systemd pid=1963 prio=120
| systemd--1         1..... 1502547us : sched_process_wait: comm=systemd pid=0 prio=120
| systemd--1         1..... 1502771us : sched_process_wait: comm=systemd pid=1964 prio=120
| systemd--1         1..... 1502819us : sched_process_wait: comm=systemd pid=0 prio=120
| systemd--1         1..... 1502835us : sched_process_wait: comm=systemd pid=0 prio=120
|   rcuc/1-31        1b...1 1524116us : sched_process_free: comm=(sd-close) pid=1964 prio=120
the gap

| systemd--1         3..... 90610397us : sched_process_wait: comm=systemd pid=0 prio=120
| systemd--1         3..... 90611469us : sched_process_wait: comm=systemd pid=1829 prio=120

So for some reason systemd stops killing tasks. It complains about still
running gpg-agent and ssh-agent but both are long gone.

Sebastian

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-25 17:59:55 [+0100], To Bert Karwatzki wrote:
> On 2026-02-25 17:37:56 [+0100], Bert Karwatzki wrote:
> > I've done two testruns with this debug patch (The persistant log buffer works now, thanks
> > again to Steven Rostedt):
> 
> …
> > This if from PREEMPT_RT log, there*s a long pause in which cgroup_task_dead() is not called
> 
> Yeah, I don't know why. The irq-work is invoked slightly delayed so that
> part is working.
…
In the good case I have
| systemd-1818  3....2 605751us : cgroup_notify_populated: root=0 id=2382 level=5 path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket val=1
|systemct-1911  1....1 620046us : cgroup_attach_task: dst_root=0 dst_id=2382 dst_level=5 dst_path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket pid=1911 comm=(ystemctl)
|systemct-1911  1..... 642680us : sched_process_exit: comm=systemctl pid=1911 prio=120 group_dead=true
|systemct-1911  1....2 643423us : signal_generate: sig=17 errno=0 code=1 comm=systemd pid=1818 grp=1 res=0
|systemct-1911  1d..2. 643432us : sched_switch: prev_comm=systemctl prev_pid=1911 prev_prio=120 prev_state=Z ==> next_comm=systemd next_pid=1818 next_prio=120

|irq_work-29    1....2 643450us : cgroup_notify_populated: root=0 id=2382 level=5 path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket val=0
|irq_work-29    1....2 643457us : cgroup_notify_populated: root=0 id=2229 level=4 path=/user.slice/user-0.slice/user@0.service/app.slice val=0
| systemd-1818  1....1 644548us : cgroup_rmdir: root=0 id=2382 level=5 path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket
| systemd-1818  1..... 644784us : sched_process_wait: comm=systemd pid=1911 prio=120

and in the bad case

| systemd-1828  3....2 312877us : cgroup_notify_populated: root=0 id=2419 level=5 path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket val=1
|systemct-1929  2....1 321916us : cgroup_attach_task: dst_root=0 dst_id=2419 dst_level=5 dst_path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket pid=1929 comm =(ystemctl)
|systemct-1929  1..... 341432us : sched_process_exit: comm=systemctl pid=1929 prio=120 group_dead=true
|systemct-1929  1.l..2 342623us : signal_generate: sig=17 errno=0 code=1 comm=systemd pid=1828 grp=1 res=0
|systemct-1929  1d..2. 342637us : sched_switch: prev_comm=systemctl prev_pid=1929 prev_prio=120 prev_state=Z ==> next_comm=systemd next_pid=1828 next_prio=120

| systemd-1828  1....1 343099us : signal_generate: sig=15 errno=0 code=0 comm=systemctl pid=1929 grp=1 res=1
| systemd-1828  1....1 343102us : signal_generate: sig=18 errno=0 code=0 comm=systemctl pid=1929 grp=1 res=1
| systemd-1828  1..... 343292us : sched_process_wait: comm=systemd pid=1929 prio=120
| systemd-1828  1..... 343442us : sched_process_wait: comm=systemd pid=0 prio=120

|irq_work-29    1....2 343725us : cgroup_notify_populated: root=0 id=2419 level=5 path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket val=0
| systemd-1828  1....1 90457054us : cgroup_rmdir: root=0 id=2419 level=5 path=/user.slice/user-0.slice/user@0.service/app.slice/ssh-agent.socket

Until the sched_switch, everything is the same. But then systemd-1828
(the one with the cgroup_notify_populated event) seems to get impatient
and sends a SIGTERM+SIGCONT. It gets the exit code, the
cgroup_notify_populated event is there later and just once. The
app.slice notify is missing. And the rmdir gets in much later.

Did systemd kill the app.slice at level=4? Is this relevant? I don't see
any immediate wake up or signal from within irq_work or
kernfs_notify_workfn() later on.

Sebastian

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

I think I've found the reason for the stall. I was looking at commit 9311e6c29b34
("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT"),
and noticed this:

+static void __init cgroup_rt_init(void)
+{
+       int cpu;
+
+       for_each_possible_cpu(cpu) {
+               init_llist_head(per_cpu_ptr(&cgrp_dead_tasks, cpu));
+               per_cpu(cgrp_dead_tasks_iwork, cpu) =
+                       IRQ_WORK_INIT_LAZY(cgrp_dead_tasks_iwork_fn);
+       }

IRQ_WORK_INIT_LAZY() expands to __IRQ_WORK_INIT(_func, IRQ_WORK_LAZY):
(in include/linux/irq_work.h)
IRQ_WORK_LAZY is declare in include/linux/smp-types.h:
	IRQ_WORK_LAZY		= 0x04, /* No IPI, wait for tick */

The "wait for tick" gave me an idea as I'm also using
CONFIG_NO_HZ_FULL=y

so I tried

commit b7453da1c7de288235234eb9265c3a2d661c1a2d (HEAD -> reboot_delay_debug_0)
Author: Bert Karwatzki <spasswolf@web.de>
Date:   Thu Feb 26 14:01:41 2026 +0100

    cgroup: use IRQ_WORK_INIT in cgroup_rt_init()
    
    Signed-off-by: Bert Karwatzki <spasswolf@web.de>

diff --git a/kernel/cgroup/cgroup.c b/kernel/cgroup/cgroup.c
index b750aa284b89..ed22842eb5d3 100644
--- a/kernel/cgroup/cgroup.c
+++ b/kernel/cgroup/cgroup.c
@@ -7047,7 +7047,7 @@ static void __init cgroup_rt_init(void)
        for_each_possible_cpu(cpu) {
                init_llist_head(per_cpu_ptr(&cgrp_dead_tasks, cpu));
                per_cpu(cgrp_dead_tasks_iwork, cpu) =
-                       IRQ_WORK_INIT_LAZY(cgrp_dead_tasks_iwork_fn);
+                       IRQ_WORK_INIT(cgrp_dead_tasks_iwork_fn);
        }
 }
 

and this seems to have fixes the issue for me. (Five successful reboots
in a row, needs more testing).

Bert Karwatzki

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-26 14:24:34 [+0100], Bert Karwatzki wrote:
> I think I've found the reason for the stall. I was looking at commit 9311e6c29b34
> ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT"),
> and noticed this:
…
I did say that removing LAZY "fixes" it in
	https://lore.kernel.org/all/20260225154341.32AjXoVi@linutronix.de/

I wouldn't describe this as a reason.
The delay leads to different behaviour and I am not sure if systemd
behaves wrongly or if there is a missing wake up.
Tejun did explain in
	https://lore.kernel.org/all/aQzg9kcnCsdRQiB4@slm.duckdns.org/

that a slight delay is okay. Something is odd here.

> and this seems to have fixes the issue for me. (Five successful reboots
> in a row, needs more testing).

> Bert Karwatzki

Sebastian

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Steven Rostedt]

On Thu, 26 Feb 2026 14:24:34 +0100
Bert Karwatzki <spasswolf@web.de> wrote:

> I think I've found the reason for the stall. I was looking at commit 9311e6c29b34
> ("cgroup: Fix sleeping from invalid context warning on PREEMPT_RT"),
> and noticed this:
> 
> +static void __init cgroup_rt_init(void)
> +{
> +       int cpu;
> +
> +       for_each_possible_cpu(cpu) {
> +               init_llist_head(per_cpu_ptr(&cgrp_dead_tasks, cpu));
> +               per_cpu(cgrp_dead_tasks_iwork, cpu) =
> +                       IRQ_WORK_INIT_LAZY(cgrp_dead_tasks_iwork_fn);
> +       }
> 
> IRQ_WORK_INIT_LAZY() expands to __IRQ_WORK_INIT(_func, IRQ_WORK_LAZY):
> (in include/linux/irq_work.h)
> IRQ_WORK_LAZY is declare in include/linux/smp-types.h:
> 	IRQ_WORK_LAZY		= 0x04, /* No IPI, wait for tick */
> 
> The "wait for tick" gave me an idea as I'm also using
> CONFIG_NO_HZ_FULL=y

If you disable NO_HZ_FULL, does the problem also go away?

I wonder if you add irq events and trace a good and bad boot to see if it
definitely shows the delayed tick being an issue.

  echo 1 > /sys/kernel/tracing/instances/boot_map/events/irq/enable

-- Steve

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-25 23:31:36 [+0100], To Bert Karwatzki wrote:
…
> Until the sched_switch, everything is the same. But then systemd-1828
> (the one with the cgroup_notify_populated event) seems to get impatient
> and sends a SIGTERM+SIGCONT. It gets the exit code, the
> cgroup_notify_populated event is there later and just once. The
> app.slice notify is missing. And the rmdir gets in much later.
…

I so proud of myself. Bert, can you confirm that this works?

--- a/kernel/cgroup/cgroup.c
+++ b/kernel/cgroup/cgroup.c
@@ -5283,6 +5283,11 @@ static void *cgroup_procs_start(struct seq_file *s, loff_t *pos)
 
 static int cgroup_procs_show(struct seq_file *s, void *v)
 {
+	struct task_struct *tsk = v;
+
+	if (READ_ONCE(tsk->__state) & TASK_DEAD)
+		return 0;
+
 	seq_printf(s, "%d\n", task_pid_vnr(v));
 	return 0;
 }
-- 
2.51.0

Sebastian

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Bert Karwatzki]

Am Freitag, dem 27.02.2026 um 15:13 +0100 schrieb Sebastian Andrzej Siewior:
> On 2026-02-25 23:31:36 [+0100], To Bert Karwatzki wrote:
> …
> > Until the sched_switch, everything is the same. But then systemd-1828
> > (the one with the cgroup_notify_populated event) seems to get impatient
> > and sends a SIGTERM+SIGCONT. It gets the exit code, the
> > cgroup_notify_populated event is there later and just once. The
> > app.slice notify is missing. And the rmdir gets in much later.
> …
> 
> I so proud of myself. Bert, can you confirm that this works?
> 
> --- a/kernel/cgroup/cgroup.c
> +++ b/kernel/cgroup/cgroup.c
> @@ -5283,6 +5283,11 @@ static void *cgroup_procs_start(struct seq_file *s, loff_t *pos)
>  
>  static int cgroup_procs_show(struct seq_file *s, void *v)
>  {
> +	struct task_struct *tsk = v;
> +
> +	if (READ_ONCE(tsk->__state) & TASK_DEAD)
> +		return 0;
> +
>  	seq_printf(s, "%d\n", task_pid_vnr(v));
>  	return 0;
>  }

I tested this with 10 reboots, it worked 9 times, one reboot was delayed (perhaps
for a different reason, sometime these delays occur on no-RT or older kernels, too)

Bert Karwatzki

Re: ~90s reboot delay with v6.19 and PREEMPT_RT

[Sebastian Andrzej Siewior]

On 2026-02-27 23:57:09 [+0100], Bert Karwatzki wrote:
> I tested this with 10 reboots, it worked 9 times, one reboot was delayed (perhaps
> for a different reason, sometime these delays occur on no-RT or older kernels, too)

Okay, thank you. I read this as Tested-by.

> Bert Karwatzki

Sebastian