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

[Bert Karwatzki <spasswolf@web.de>]

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