With SELINUX and PREEMPT_RT enabled, we started finding shutdowns could take about 30 seconds. And that became noticable enough to stop us in our tracks upgrading a customer project from 7.0 to 7.1 before we could understand what had gone wrong.

My colleague Alen started out the investigation by searching for the pattern that seemed to implicate the regression, and soon determined that with PREEMPT_RT off, the issue goes away. But that wasn’t the end of it… we could also find cases where with PREEMPT_RT enabled the shutdown was nice and fast.

Something else is afoot, so we needed to explore deeper. With some more testing, and digging, we discovered that in fact we had an initramfs enabling SELinux in the scenario that was slow, and we came to the theory that a combination of both SELinux and PREEMPT_RT was required as the repeatable parameters.

But it still wasn’t clear when the issue was caused, or how to reproduce it on another system. With various iterations of testing with adding ‘selinux=0’, ‘enforcing=0’, ‘audit=0’, on the commandline, we could only see selinux causing any effects, yet a different platform with the same SoC with SELinux enabled showed no issue.

Tracing systemd:

As this is visible with the systemd shutdown procedure, lets start there. Systemd reports we can diagnose shutdown issues (https://systemd.io/DEBUGGING/) with:

Shutdown Completes Eventually

If normal reboot or poweroff work, but take a suspiciously long time, then

    boot with the debug options:

systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on enforcing=0

    save the following script as /usr/lib/systemd/system-shutdown/debug.sh and make it executable:

#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /

    reboot

Look for timeouts logged in the resulting file shutdown-log.txt and/or attach it to a bugreport.

Running this generated a 1MB log file, but with some very interesting results:

[  223.048194] systemd[1]: auditd.service: Releasing resources...
[  223.048697] systemd[1]: Child 870 (systemd-resolve) died (code=exited, status=0/SUCCESS)
[  223.048943] systemd[1]: systemd-resolved.service: Child 870 belongs to systemd-resolved.service.
[  223.049008] systemd[1]: systemd-resolved.service: Main process exited, code=exited, status=0/SUCCESS (success)
[  223.049287] systemd[1]: systemd-resolved.service: Deactivated successfully.
[  223.049396] systemd[1]: systemd-resolved.service: Service restart not allowed.
[  223.049431] systemd[1]: systemd-resolved.service: Changed stop-sigterm -> dead
[  223.695800] systemd[1]: systemd-resolved.service: Failed to remove cgroup control inotify watch 32 for systemd-resolved.service, ignoring: Invalid argument
[  223.695877] systemd[1]: systemd-resolved.service: Failed to remove cgroup memory inotify watch 33 for systemd-resolved.service, ignoring: Invalid argument
[  223.711287] systemd[1]: systemd-resolved.service: Job 675 systemd-resolved.service/stop finished, result=done
[  223.711327] systemd[1]: Stopped Network Name Resolution.
[  223.751408] systemd[1]: systemd-resolved-varlink.socket: Changed running -> listening

Note that ‘700ish’ millisecond delay between “Changed stop-sigterm” and “Failed to remove cgroup”. So the first instinct was to look at cgroup interactions. But how do we test that? Lets dig deeper into the cgroups:

Cgroups

(cgroupfs)[https://docs.redhat.com/en/documentation/red_hat_enterprise_linux/10/html/managing_monitoring_and_updating_the_kernel/using-cgroupfs-to-manually-manage-cgroups] lets us manage cgroups directly. And what became apparent quite quickly was the difference in creating cgroups vs removing them:

root@blubbel:~# time mkdir /sys/fs/cgroup/cgroup-test
real	0m 0.02s
user	0m 0.00s
sys	0m 0.01s
root@blubbel:~# time rmdir /sys/fs/cgroup/cgroup-test
real	0m 0.88s
user	0m 0.01s
sys	0m 0.01s

Aha! - An 0.88s time measured to remove a cgroup. That sounds suspiciously like the 0.7s delay we saw stopping a task above!

Now - we might have a reproducer. A bit more testing with selinux enabled and disabled shows that this really is where we see a change:

# selinux=1
root@blubbel:~# mkdir /sys/fs/cgroup/test-cgroup
root@blubbel:~# time rmdir /sys/fs/cgroup/test-cgroup
real	0m 0.77s
user	0m 0.00s
sys	0m 0.00s

....

# selinux=0
root@blubbel:~# mkdir /sys/fs/cgroup/test-cgroup
root@blubbel:~# time rmdir /sys/fs/cgroup/test-cgroup
real	0m 0.00s
user	0m 0.00s
sys	0m 0.00s

So … removing a cgroup with selinux enabled somehow takes more than 700ms. That’s certainly not very friendly.

That also means this impacts startup and other tasks too, and perhaps this slowdown is interacting or impeding other parts of the system - but just isn’t as visible as shutdown, so I really wanted to get to the bottom of this one.

• Tune in next week to see where this goes!

Benefits

• Bisecting mainline to find the fault
• Stable trees
• Bisecting stable to find the fixes

Benefits of bisection

Benefits of long term stables

Benefits of automation/lessons learned.

• Check the latest stable trees earlier
• Automate the bisections earlier.
  • First run of bisect failed because of user error during /long/ running operations.
  • Automations remove the human element of losing track.