Slow shutdown and rebooting when shutdown

norse · May 12, 2022, 6:20am

Hello all,
I'm having slow shut down speeds that seem to be caused by the process "A stop job is running for Session 2 of [user] " that eventually times out.

On top of that, occasionally when I shut Garuda down having taken this time, it actually reboots.

Has anyone else had this issue?

garuda-inxi
System:
Kernel: 5.17.6-zen1-1-zen arch: x86_64 bits: 64 compiler: gcc v: 12.1.0
parameters: BOOT_IMAGE=/@/boot/vmlinuz-linux-zen
root=UUID=e138e3b5-1773-48b5-a56c-3a032b23b70a rw rootflags=subvol=@
quiet splash rd.udev.log_priority=3 vt.global_cursor_default=0 loglevel=3
Desktop: KDE Plasma v: 5.24.5 tk: Qt v: 5.15.3 info: latte-dock
wm: kwin_x11 vt: 1 dm: SDDM Distro: Garuda Linux base: Arch Linux
Machine:
Type: Desktop System: Micro-Star product: MS-7B51 v: 1.0
serial: <superuser required>
Mobo: Micro-Star model: MPG Z390 GAMING PLUS (MS-7B51) v: 1.0
serial: <superuser required> UEFI: American Megatrends v: 1.C0
date: 10/10/2020
Battery:
Device-1: hidpp_battery_0 model: Logitech Wireless Keyboard
serial: <filter> charge: 55% (should be ignored) rechargeable: yes
status: discharging
CPU:
Info: model: Intel Core i5-9600K bits: 64 type: MCP arch: Coffee Lake
family: 6 model-id: 0x9E (158) stepping: 0xD (13) microcode: 0xF0
Topology: cpus: 1x cores: 6 smt: <unsupported> cache: L1: 384 KiB
desc: d-6x32 KiB; i-6x32 KiB L2: 1.5 MiB desc: 6x256 KiB L3: 9 MiB
desc: 1x9 MiB
Speed (MHz): avg: 4220 high: 4560 min/max: 800/4600 scaling:
driver: intel_pstate governor: performance cores: 1: 4442 2: 4560 3: 4483
4: 4028 5: 3325 6: 4486 bogomips: 44398
Flags: avx avx2 ht lm nx pae sse sse2 sse3 sse4_1 sse4_2 ssse3 vmx
Vulnerabilities:
Type: itlb_multihit status: KVM: VMX disabled
Type: l1tf status: Not affected
Type: mds status: Not affected
Type: meltdown status: Not affected
Type: spec_store_bypass
mitigation: Speculative Store Bypass disabled via prctl
Type: spectre_v1
mitigation: usercopy/swapgs barriers and __user pointer sanitization
Type: spectre_v2
mitigation: Enhanced IBRS, IBPB: conditional, RSB filling
Type: srbds mitigation: TSX disabled
Type: tsx_async_abort mitigation: TSX disabled
Graphics:
Device-1: NVIDIA TU117 [GeForce GTX 1650] vendor: Gigabyte driver: nvidia
v: 510.68.02 alternate: nouveau,nvidia_drm pcie: gen: 3 speed: 8 GT/s
lanes: 16 bus-ID: 01:00.0 chip-ID: 10de:1f82 class-ID: 0300
Device-2: Realtek EKACOM-K20E type: USB driver: snd-usb-audio,uvcvideo
bus-ID: 1-3:2 chip-ID: 0bda:5696 class-ID: 0102 serial: <filter>
Display: x11 server: X.Org v: 21.1.3 with: Xwayland v: 22.1.1
compositor: kwin_x11 driver: X: loaded: nvidia unloaded: modesetting
alternate: fbdev,nouveau,nv,vesa gpu: nvidia display-ID: :0 screens: 1
Screen-1: 0 s-res: 1920x1080 s-dpi: 93 s-size: 524x292mm (20.63x11.50")
s-diag: 600mm (23.62")
Monitor-1: HDMI-0 res: 1920x1080 hz: 60 dpi: 94
size: 521x293mm (20.51x11.54") diag: 598mm (23.53") modes: N/A
OpenGL: renderer: NVIDIA GeForce GTX 1650/PCIe/SSE2
v: 4.6.0 NVIDIA 510.68.02 direct render: Yes
Audio:
Device-1: Intel Cannon Lake PCH cAVS vendor: Micro-Star MSI
driver: snd_hda_intel v: kernel
alternate: snd_soc_skl,snd_sof_pci_intel_cnl bus-ID: 00:1f.3
chip-ID: 8086:a348 class-ID: 0403
Device-2: NVIDIA vendor: Gigabyte driver: snd_hda_intel v: kernel pcie:
gen: 3 speed: 8 GT/s lanes: 16 bus-ID: 01:00.1 chip-ID: 10de:10fa
class-ID: 0403
Device-3: Realtek EKACOM-K20E type: USB driver: snd-usb-audio,uvcvideo
bus-ID: 1-3:2 chip-ID: 0bda:5696 class-ID: 0102 serial: <filter>
Sound Server-1: ALSA v: k5.17.6-zen1-1-zen running: yes
Sound Server-2: PulseAudio v: 15.0 running: no
Sound Server-3: PipeWire v: 0.3.51 running: yes
Network:
Device-1: Intel Cannon Lake PCH CNVi WiFi driver: iwlwifi v: kernel
bus-ID: 00:14.3 chip-ID: 8086:a370 class-ID: 0280
IF: wlo1 state: up mac: <filter>
Device-2: Intel Ethernet I219-V vendor: Micro-Star MSI driver: e1000e
v: kernel port: N/A bus-ID: 00:1f.6 chip-ID: 8086:15bc class-ID: 0200
IF: eno2 state: up speed: 100 Mbps duplex: full mac: <filter>
Bluetooth:
Device-1: Intel Bluetooth 9460/9560 Jefferson Peak (JfP) type: USB
driver: btusb v: 0.8 bus-ID: 1-14:5 chip-ID: 8087:0aaa class-ID: e001
Report: bt-adapter ID: hci0 rfk-id: 0 state: down
bt-service: enabled,running rfk-block: hardware: no software: yes
address: <filter>
Drives:
Local Storage: total: 7.06 TiB used: 258.58 GiB (3.6%)
SMART Message: Unable to run smartctl. Root privileges required.
ID-1: /dev/nvme0n1 maj-min: 259:1 vendor: Western Digital
model: WDS500G2B0C-00PXH0 size: 465.76 GiB block-size: physical: 512 B
logical: 512 B speed: 31.6 Gb/s lanes: 4 type: SSD serial: <filter>
rev: 211210WD temp: 35.9 C scheme: GPT
ID-2: /dev/nvme1n1 maj-min: 259:9 vendor: KingSpec model: NE-256
size: 238.47 GiB block-size: physical: 512 B logical: 512 B
speed: 31.6 Gb/s lanes: 4 type: SSD serial: <filter> rev: T1106A0
temp: 40.9 C scheme: GPT
ID-3: /dev/nvme2n1 maj-min: 259:0 vendor: Western Digital
model: WDS100T3X0C-00SJG0 size: 931.51 GiB block-size: physical: 512 B
logical: 512 B speed: 31.6 Gb/s lanes: 4 type: SSD serial: <filter>
rev: 111110WD temp: 34.9 C scheme: GPT
ID-4: /dev/sda maj-min: 8:0 vendor: Western Digital
model: WDS100T2B0A-00SM50 size: 931.51 GiB block-size: physical: 512 B
logical: 512 B speed: 6.0 Gb/s type: SSD serial: <filter> rev: 00WD
scheme: GPT
ID-5: /dev/sdb maj-min: 8:16 vendor: Western Digital
model: WD30EFRX-68EUZN0 size: 2.73 TiB block-size: physical: 4096 B
logical: 512 B speed: 6.0 Gb/s type: HDD rpm: 5400 serial: <filter>
rev: 0A82 scheme: GPT
ID-6: /dev/sdc maj-min: 8:32 vendor: Western Digital
model: WD20PURZ-85GU6Y0 size: 1.82 TiB block-size: physical: 4096 B
logical: 512 B speed: 6.0 Gb/s type: HDD rpm: 5400 serial: <filter>
rev: 0A80 scheme: GPT
Partition:
ID-1: / raw-size: 465.46 GiB size: 465.46 GiB (100.00%)
used: 258.58 GiB (55.6%) fs: btrfs dev: /dev/nvme0n1p2 maj-min: 259:8
ID-2: /boot/efi raw-size: 300 MiB size: 299.4 MiB (99.80%)
used: 580 KiB (0.2%) fs: vfat dev: /dev/nvme0n1p1 maj-min: 259:7
ID-3: /home raw-size: 465.46 GiB size: 465.46 GiB (100.00%)
used: 258.58 GiB (55.6%) fs: btrfs dev: /dev/nvme0n1p2 maj-min: 259:8
ID-4: /var/log raw-size: 465.46 GiB size: 465.46 GiB (100.00%)
used: 258.58 GiB (55.6%) fs: btrfs dev: /dev/nvme0n1p2 maj-min: 259:8
ID-5: /var/tmp raw-size: 465.46 GiB size: 465.46 GiB (100.00%)
used: 258.58 GiB (55.6%) fs: btrfs dev: /dev/nvme0n1p2 maj-min: 259:8
Swap:
Kernel: swappiness: 133 (default 60) cache-pressure: 100 (default)
ID-1: swap-1 type: zram size: 31.29 GiB used: 2.2 MiB (0.0%)
priority: 100 dev: /dev/zram0
Sensors:
System Temperatures: cpu: 27.8 C pch: 60.0 C mobo: N/A gpu: nvidia
temp: 53 C
Fan Speeds (RPM): N/A gpu: nvidia fan: 0%
Info:
Processes: 295 Uptime: 12m wakeups: 2 Memory: 31.29 GiB
used: 4.02 GiB (12.9%) Init: systemd v: 250 tool: systemctl Compilers:
gcc: 12.1.0 clang: 13.0.1 Packages: pacman: 1894 lib: 527 Shell: fish
v: 3.4.1 default: Bash v: 5.1.16 running-in: konsole inxi: 3.3.15
Garuda (2.6.2-1):
System install date:     2022-04-03
Last full system update: 2022-05-12
Is partially upgraded:   No
Relevant software:       NetworkManager
Windows dual boot:       Probably (Run as root to verify)
Snapshots:               Snapper (maybe)
Failed units:

FGD · May 12, 2022, 10:29am

That is very common. Any distro can face this situation, most of the time it’s related to “some application/process” a user was running just before shutdown/reboot and for “some reason” that process cannot be killed by the system, so it times out, usually around 90sec, until it is forcibly killed.

A very good way to put your finger on that is by looking at

journalctl -r -b -1

This will display your log from last boot (so after it timed out during the last shutdown) and by looking at the timestamp you can identify one hole of about 90sec, a jump in timestamp around that value. Take note of the exact time you initiated the reboot and make sure it corresponds to that moment in the log.

If you can display that log showing this, it will help identify what causes it to time out. Most of the time…

Thy · May 12, 2022, 3:30pm

As stated already this is just a thing that happens on any distro depending on a lot of things... I experience this on occasion when I had been copying over files to a USB stick and even tho I had safely removed it already, it hangs for some reason.

norse · May 12, 2022, 7:53pm

I had just booted in and read this, and shutdown successfully with no delay or unwanted reboot.
On reboot I opened 2 browsers - brave and librewolf, opened settings/octopi.. a few other programs to try and force the fault and shutdown again - this had the desired effect of the time out and uncalled for reboot.
I have a gut feeling that librewolf is causing this somehow.

For some reason the terminal dump does not show increments of the timing in the log or show 1 minute 30 second wait, and all gives the impression that everything happened instantly:

journalctl -r -b -1
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /root.
May 12 20:38:57 john-ms7b51 systemd[1]: root.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /home/guest.
May 12 20:38:57 john-ms7b51 systemd[1]: home-guest.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /boot/efi.
May 12 20:38:57 john-ms7b51 systemd[1]: boot-efi.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit: BPF prog-id=0 op=UNLOAD
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Flush Journal to Persistent Storage...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/cache...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting Temporary Directory /tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /srv...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /root...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /home/guest...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /boot/efi...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local File Systems.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Create Volatile Files and Directories.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp co>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Record System Boot/Shutdown in UTMP.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-update-utmp.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Network Time Synchronization.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-timesyncd.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[17206]: SYSTEM_SHUTDOWN pid=17206 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-u>
lines 1-27...skipping...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /root.
May 12 20:38:57 john-ms7b51 systemd[1]: root.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /home/guest.
May 12 20:38:57 john-ms7b51 systemd[1]: home-guest.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /boot/efi.
May 12 20:38:57 john-ms7b51 systemd[1]: boot-efi.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit: BPF prog-id=0 op=UNLOAD
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Flush Journal to Persistent Storage...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/cache...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting Temporary Directory /tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /srv...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /root...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /home/guest...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /boot/efi...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local File Systems.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe=>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Create Volatile Files and Directories.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp comm="systemd" exe="/u>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Record System Boot/Shutdown in UTMP.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-update-utmp.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Network Time Synchronization.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-timesyncd.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[17206]: SYSTEM_SHUTDOWN pid=17206 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp" exe="/us>
May 12 20:38:57 john-ms7b51 systemd[1]: Unset automount Arbitrary Executable File Formats File System Automount Point.
lines 1-28...skipping...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /root.
May 12 20:38:57 john-ms7b51 systemd[1]: root.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /home/guest.
May 12 20:38:57 john-ms7b51 systemd[1]: home-guest.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /boot/efi.
May 12 20:38:57 john-ms7b51 systemd[1]: boot-efi.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit: BPF prog-id=0 op=UNLOAD
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Flush Journal to Persistent Storage...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/cache...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting Temporary Directory /tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /srv...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /root...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /home/guest...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /boot/efi...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local File Systems.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Create Volatile Files and Directories.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Record System Boot/Shutdown in UTMP.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-update-utmp.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr/lib/s>
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Network Time Synchronization.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-timesyncd.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[17206]: SYSTEM_SHUTDOWN pid=17206 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp" exe="/usr/lib/>
May 12 20:38:57 john-ms7b51 systemd[1]: Unset automount Arbitrary Executable File Formats File System Automount Point.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.automount: Deactivated successfully.
lines 1-29...skipping...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /root.
May 12 20:38:57 john-ms7b51 systemd[1]: root.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /home/guest.
May 12 20:38:57 john-ms7b51 systemd[1]: home-guest.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /boot/efi.
May 12 20:38:57 john-ms7b51 systemd[1]: boot-efi.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit: BPF prog-id=0 op=UNLOAD
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Flush Journal to Persistent Storage...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/cache...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting Temporary Directory /tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /srv...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /root...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /home/guest...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /boot/efi...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local File Systems.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Create Volatile Files and Directories.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Record System Boot/Shutdown in UTMP.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-update-utmp.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Network Time Synchronization.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-timesyncd.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[17206]: SYSTEM_SHUTDOWN pid=17206 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Unset automount Arbitrary Executable File Formats File System Automount Point.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.automount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-binfmt comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
lines 1-30...skipping...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /root.
May 12 20:38:57 john-ms7b51 systemd[1]: root.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /home/guest.
May 12 20:38:57 john-ms7b51 systemd[1]: home-guest.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounted /boot/efi.
May 12 20:38:57 john-ms7b51 systemd[1]: boot-efi.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit: BPF prog-id=0 op=UNLOAD
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Flush Journal to Persistent Storage...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /var/cache...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting Temporary Directory /tmp...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /srv...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /root...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /home/guest...
May 12 20:38:57 john-ms7b51 systemd[1]: Unmounting /boot/efi...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local File Systems.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Create Volatile Files and Directories.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Record System Boot/Shutdown in UTMP.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-update-utmp.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Network Time Synchronization.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-timesyncd.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[17206]: SYSTEM_SHUTDOWN pid=17206 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Unset automount Arbitrary Executable File Formats File System Automount Point.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.automount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-binfmt comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Set Up Additional Binary Formats.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local File Systems.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Create Volatile Files and Directories.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-tmpfiles-setup.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-update-utmp comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Record System Boot/Shutdown in UTMP.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-update-utmp.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Network Time Synchronization.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-timesyncd.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.mount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[17206]: SYSTEM_SHUTDOWN pid=17206 uid=0 auid=4294967295 ses=4294967295 msg=' comm="systemd-update-utmp" exe="/usr/lib/systemd/systemd-update-utmp" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Unset automount Arbitrary Executable File Formats File System Automount Point.
May 12 20:38:57 john-ms7b51 systemd[1]: proc-sys-fs-binfmt_misc.automount: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-binfmt comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Set Up Additional Binary Formats.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-binfmt.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Record System Boot/Shutdown in UTMP...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Network Time Synchronization...
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-modules-load comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Load Kernel Modules.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-modules-load.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Apply Kernel Variables.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-sysctl.service: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping Set Up Additional Binary Formats...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local Verity Protected Volumes.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local Integrity Protected Volumes.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Forward Password Requests to Wall Directory Watch.
May 12 20:38:57 john-ms7b51 systemd[1]: systemd-ask-password-wall.path: Deactivated successfully.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped target Local Encrypted Volumes.`
type or paste code here

FGD · May 12, 2022, 8:04pm

Is there something further down below the log with different timestamp?

norse · May 12, 2022, 8:37pm

Ahh, yes I managed to lose some of the log. Here's what was missed off:

May 12 20:38:57 john-ms7b51 systemd-logind[621]: Removed session 2.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping User Manager for UID 1000...
May 12 20:38:57 john-ms7b51 systemd[1]: Stopping User Login Management...
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Consumed 1min 55.822s CPU time.
May 12 20:38:57 john-ms7b51 systemd[1]: Stopped Session 2 of User john.
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Failed with result 'timeout'.
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Killing process 4222 (CPMMListener) with signal SIGK>
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Killing process 4114 (QQmlThread) with signal SIGKIL>
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Killing process 4055 (kwin_x11) with signal SIGKILL.
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Stopping timed out. Killing.
May 12 20:37:39 john-ms7b51 kernel: Console: switching to colour frame buffer device 128x48
May 12 20:37:39 john-ms7b51 kernel: fbcon: Taking over console
May 12 20:37:35 john-ms7b51 uresourced[3179]: Setting resources on user.slice (MemoryMin: 0, MemoryLow: 0, CP>
May 12 20:37:35 john-ms7b51 uresourced[3179]: Setting resources on user@1000.service (MemoryMin: 0, MemoryLow>
May 12 20:37:35 john-ms7b51 uresourced[3179]: Setting resources on user-1000.slice (MemoryMin: 0, MemoryLow: >
May 12 20:37:31 john-ms7b51 dbus-daemon[605]: [system] Activation via systemd failed for unit 'dbus-org.freed>
May 12 20:37:31 john-ms7b51 dbus-daemon[605]: [system] Activating via systemd: service name='org.freedesktop.>
May 12 20:37:27 john-ms7b51 systemd[1]: Tell Plymouth To Jump To initramfs was skipped because of a failed co>
May 12 20:37:27 john-ms7b51 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plym>
May 12 20:37:27 john-ms7b51 systemd[1]: Started Show Plymouth Reboot Screen.
May 12 20:37:27 john-ms7b51 systemd[1]: Received SIGRTMIN+20 from PID 17038 (plymouthd).
May 12 20:37:27 john-ms7b51 audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=plymo>
May 12 20:37:27 john-ms7b51 systemd[1]: Starting Show Plymouth Reboot Screen...
May 12 20:37:27 john-ms7b51 systemd[1]: Stopped Terminate Plymouth Boot Screen.
May 12 20:37:27 john-ms7b51 systemd[1]: plymouth-quit.service: Deactivated successfully.

FGD · May 13, 2022, 12:25am

norse:

May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Killing process 4222 (CPMMListener) with signal SIGK>
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Killing process 4114 (QQmlThread) with signal SIGKIL>
May 12 20:38:57 john-ms7b51 systemd[1]: session-2.scope: Killing process 4055 (kwin_x11) with signal SIGKILL.

That seems to be the problem. Those 3 processes (or possibly 1 of the 3 blocking the other 2) seem to have caused the freeze on shutdown.

You can see that by the jump in time here

However, it’s weird, it seems kwin itself timed out, or got forced to time out from 1 or the other 2 above…

Not sure how to approach this, maybe google for something like “kwin times out on shutdown” or “A stop job is running for Session kwin” (no need to put more after “session” but include “kwin” somewhere in there so I usually insert at the end) or something similar?

You could and probably should also search the same thing for “QQmlThread” and “CPMMListener”.

Another possibility would be to disable one of those things and test it out. CPMM seems to be a TCP Listener, if you installed this, try to not run it.

As for QQml, it’s called by kwin_x11, so if kwin_x11 is timing out, maybe it drags QQml along with it, meaning I would first start looking at that TCP Listener before going down the kwin or QQml route.

If checking the QQml, try disabling your Compositor completely and see if that fixes the issue. Actually that’s pretty easy to try, you could try that first if you know NOTHING about that TCP Listener.

FGD · May 13, 2022, 12:46am

Ah well, it's always later that you find something... lolll

This guy has an apparent same problem systemd stop job for Session 2 on shutdown / Newbie Corner / Arch Linux Forums

This guy too [kwin] [Bug 445385] New: Slow shutdown problems due to kwin

FGD · May 13, 2022, 12:50am

Right so basically the key in this situation is 4 steps in most cases:

Get your logs (journalctl -r -b -1) from last boot (assuming last shutdown was slow)
Identify the jump in time equal to the time it froze on shutdown (usually 90sec! Could be 30 and I guess anything else that is "too much")
Check what your log says about time outs, killing stuff, etc. around that jump in time
Get key words out of that (here it's kwin_x11, QQmlThread and CPMMListener) and google for all that in various ways

That should bring you to a lot of posts to read and hopefully one of those will have a valid fix.

norse · May 13, 2022, 11:16am

Cheers, thanks for that FGD.

system · May 27, 2022, 11:16am

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.