Arch Linux

Nimamoh

Member

Registered: 2016-03-05

Posts: 8

[SOLVED] Long shutdown / reboot - unable to track what's wrong

Hello,

I'm experimenting very long shutdown with arch. Here is

systemctl -b -1

mai 03 18:38:55 DREADNOUGH kernel: Linux version 5.0.10-arch1-1-ARCH (builduser@heftig-2592) (gcc version 8.3.0 (GCC)>
mai 03 18:38:55 DREADNOUGH kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-linux root=UUID=c1dd377b-a6be-48dd-8f11-8c2>
mai 03 18:38:55 DREADNOUGH kernel: KERNEL supported cpus:
mai 03 18:38:55 DREADNOUGH kernel:   Intel GenuineIntel
mai 03 18:38:55 DREADNOUGH kernel:   AMD AuthenticAMD
mai 03 18:38:55 DREADNOUGH kernel:   Hygon HygonGenuine
mai 03 18:38:55 DREADNOUGH kernel:   Centaur CentaurHauls
mai 03 18:38:55 DREADNOUGH kernel: x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
mai 03 18:38:55 DREADNOUGH kernel: x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
mai 03 18:38:55 DREADNOUGH kernel: x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
mai 03 18:38:55 DREADNOUGH kernel: x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
mai 03 18:38:55 DREADNOUGH kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'compacted'>
mai 03 18:38:55 DREADNOUGH kernel: BIOS-provided physical RAM map:
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000000a0000-0x00000000000fffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x0000000000100000-0x0000000009cfffff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x0000000009d00000-0x0000000009ffffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x000000000a000000-0x000000000a1fffff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x000000000a200000-0x000000000a209fff] ACPI NVS
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x000000000a20a000-0x000000000affffff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x000000000b000000-0x000000000b01ffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x000000000b020000-0x00000000dbafafff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000dbafb000-0x00000000dbc72fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000dbc73000-0x00000000dbdf5fff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000dbdf6000-0x00000000dc20efff] ACPI NVS
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000dc20f000-0x00000000dce3ffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000dce40000-0x00000000dced5fff] type 20
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000dced6000-0x00000000deffffff] usable
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000df000000-0x00000000dfffffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000f8000000-0x00000000fbffffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fd100000-0x00000000fdffffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fea00000-0x00000000fea0ffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000feb80000-0x00000000fec01fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fec10000-0x00000000fec10fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fec30000-0x00000000fec30fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fed00000-0x00000000fed00fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fed40000-0x00000000fed44fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fed80000-0x00000000fed8ffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fedc2000-0x00000000fedcffff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fedd4000-0x00000000fedd5fff] reserved
mai 03 18:38:55 DREADNOUGH kernel: BIOS-e820: [mem 0x00000000fee00000-0x00000000feefffff] reserved
...skipping...
mai 03 18:40:06 DREADNOUGH systemd[1]: systemd-fsck@dev-disk-by\x2duuid-DAB2\x2dBF38.service: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped File System Check on /dev/disk/by-uuid/DAB2-BF38.
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck@d>
mai 03 18:40:06 DREADNOUGH systemd[1]: home.mount: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Unmounted /home.
mai 03 18:40:06 DREADNOUGH systemd[1]: Reached target Unmount All Filesystems.
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck@d>
mai 03 18:40:06 DREADNOUGH systemd[1]: systemd-fsck@dev-disk-by\x2duuid-84b3d8df\x2d77a6\x2d4259\x2dafaf\x2d3939d92ec>
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped File System Check on /dev/disk/by-uuid/84b3d8df-77a6-4259-afaf-3939d92>
mai 03 18:40:06 DREADNOUGH systemd[1]: Removed slice system-systemd\x2dfsck.slice.
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped target Local File Systems (Pre).
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopping Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress>
mai 03 18:40:06 DREADNOUGH systemd[1]: systemd-remount-fs.service: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped Remount Root and Kernel File Systems.
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-remoun>
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfil>
mai 03 18:40:06 DREADNOUGH systemd[1]: systemd-tmpfiles-setup-dev.service: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped Create Static Device Nodes in /dev.
mai 03 18:40:06 DREADNOUGH systemd[1]: lvm2-monitor.service: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress >
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lvm2-monitor c>
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopping LVM2 metadata daemon...
mai 03 18:40:06 DREADNOUGH systemd[1]: lvm2-lvmetad.service: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Stopped LVM2 metadata daemon.
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lvm2-lvmetad c>
mai 03 18:40:06 DREADNOUGH systemd[1]: Reached target Shutdown.
mai 03 18:40:06 DREADNOUGH systemd[1]: Reached target Final Step.
mai 03 18:40:06 DREADNOUGH systemd[1]: systemd-reboot.service: Succeeded.
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-reboo>
mai 03 18:40:06 DREADNOUGH audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-reboot>
mai 03 18:40:06 DREADNOUGH systemd[1]: Started Reboot.
mai 03 18:40:06 DREADNOUGH systemd[1]: Reached target Reboot.
mai 03 18:40:06 DREADNOUGH systemd[1]: lvm2-lvmetad.socket: Succeeded.
mai 03 18:40:06 DREADNOUGH systemd[1]: Closed LVM2 metadata daemon socket.
mai 03 18:40:06 DREADNOUGH systemd[1]: Shutting down.
mai 03 18:40:06 DREADNOUGH systemd[1]: Hardware watchdog 'SP5100 TCO timer', version 0
mai 03 18:40:06 DREADNOUGH systemd[1]: Set hardware watchdog to 10min.
mai 03 18:40:06 DREADNOUGH kernel: watchdog: watchdog0: watchdog did not stop!
mai 03 18:40:06 DREADNOUGH kernel: printk: systemd-shutdow: 56 output lines suppressed due to ratelimiting
mai 03 18:40:06 DREADNOUGH systemd-shutdown[1]: Syncing filesystems and block devices.
mai 03 18:40:06 DREADNOUGH systemd-shutdown[1]: Sending SIGTERM to remaining processes...
mai 03 18:40:06 DREADNOUGH systemd-journald[415]: Journal stopped

What does't appear is that the tty during shutdown hangs during a few minutes then output that it could not unmount several devices then shutdown. (I do not have time to read messages before it shutdowns)

I've also tried to disable ratelimiting on kernel:

# echo 0 > /proc/sys/kernel/printk_ratelimit

# echo 0 > /proc/sys/kernel/printk_ratelimit_burst

and systemd, setting 0 in 

RateLimitIntervalSec

RateLimitBurst

in file

/etc/systemd/journald.conf

but output still supress line through ratelimiting (as shown above).

I'm out of idea to know what's happening during shutdown and what takes so much time....

Last edited by Nimamoh (2019-05-05 15:50:34)

Mortimer Houghton

Member

Registered: 2014-09-28

Posts: 89

Re: [SOLVED] Long shutdown / reboot - unable to track what's wrong

Maybe you could try this script to check for timeouts: Systemd - Debugging - Diagnosing Shutdown Problems

seth

Member

From: Don't DM me only for attention

Registered: 2012-09-03

Posts: 74,307

Re: [SOLVED] Long shutdown / reboot - unable to track what's wrong

https://bbs.archlinux.org/viewtopic.php … 2#p1835892

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Nimamoh

Member

Registered: 2016-03-05

Posts: 8

Re: [SOLVED] Long shutdown / reboot - unable to track what's wrong

@Mortimer Houghton
I followed the steps as depicted in the guide, it showed me more informations, but I couldn't track down anything useful (it's not as if I know what I'm looking for)

Here is a 'tac' command of /shutdown-log.txt

https://termbin.com/93km

Same thing with systemd log:

https://termbin.com/v1ew

@Seth
I don't think it's related, I tried with a lts kernel, got the same issue - masking lvm2 services doesn't impact my issue

Last edited by Nimamoh (2019-05-04 00:52:21)

Mortimer Houghton

Member

Registered: 2014-09-28

Posts: 89

Re: [SOLVED] Long shutdown / reboot - unable to track what's wrong

Can you try changing (and uncommenting) "DefaultTimeoutStopSec=90s" in /etc/systemd/system.conf?  Change it from 90 to something like 5.  I noticed that the shutdown-log you got from debugging follows the systemd log until journaling ends, at which point it seems to hang for almost exactly 90 seconds before finally sending a sigkill to the remaining processes.  Perhaps these are related?  Also, that sigkill is to "qemu-system-i386".  Are you running an emulator?  This is what I would look at.

seth

Member

From: Don't DM me only for attention

Registered: 2012-09-03

Posts: 74,307

Re: [SOLVED] Long shutdown / reboot - unable to track what's wrong

I do not have time to read messages before it shuts down

Do you have a camera?

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

Nimamoh

Member

Registered: 2016-03-05

Posts: 8

Re: [SOLVED] Long shutdown / reboot - unable to track what's wrong

@Seth

Yeah, I managed to capture the last messaging, it actually is messages about umounting cgroups related mount points successfully.

@Mortimer

I didn't try to change the timeout yet but your guess was right, that's qemu-system-i386 that is problematic, actually it's a zombie process that seem to be started by libvirtd daemon at boot time.
I don't know why libvirtd starts such a process on its own when it boots (it's even more weird that starting it manually doesn't trigger any qemu zombie process)

For now I disabled the libvirtd daemon to fix my issue, I'll complete this thread if I find something about this zombie process.