[systemd-devel] umount fails on system with huge (2TiB) buff/cache
Holger Kiehl
Holger.Kiehl at dwd.de
Fri Jan 26 12:13:34 UTC 2024
Hello,
with huge memory buff/cache a umount can take very long:
time umount /mnt/u2
real 10m43.026s
user 0m0.000s
sys 10m27.985s
which then causes a system not to umount the device properly when
rebooting, watching serial console:
[ OK ] Deactivated swap /dev/sda4.
[ OK ] Unmounted /boot.
[ OK ] Deactivated swap /dev/disk…0-c79c-4437-922e-21bb8c926cf8.
[ OK ] Stopped File System Check …9-80c6-4dc9-86db-f3a9ec179b3c.
[244820.237512] audit: type=1131 audit(1706268318.490:23423): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck at dev-disk-by\x2duuid-d079cce9\x2d80c6\x2d4dc9\x2d86db\x2df3a9ec179b3c comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Stopped File System Check on /dev/mapper/datao1db.
[244820.273498] audit: type=1131 audit(1706268318.526:23424): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck at dev-mapper-datao1db comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Unmounted /mnt/hdd1.
[ OK ] Stopped File System Check on /dev/mapper/datao1da.
[244820.409479] audit: type=1131 audit(1706268318.662:23425): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck at dev-mapper-datao1da comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ ***] A stop job is running for /mnt/u2 (2min 55s / no limit)
Note it states 'no limit' and one can see after some minutes it says
it umounted /mnt/u2:
[ OK ] Unmounted /mnt/u2.
[ OK ] Reached target Unmount All Filesystems.
[ OK ] Stopped File System Check …f-5fca-4f3b-b51d-9bd61b3afed2.
[245090.427777] audit: type=1131 audit(1706268588.681:23426): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck at dev-disk-by\x2duuid-37da47ff\x2d5fca\x2d4f3b\x2db51d\x2d9bd61b3afed2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Removed slice Slice /system/systemd-fsck.
[ OK ] Stopped target Preparation for Local File Systems.
Stopping Device-Mapper Multipath Device Controller...
[ OK ] Stopped Remount Root and Kernel File Systems.
[245090.487727] audit: type=1131 audit(1706268588.741:23427): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-remount-fs comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Stopped File System Check on Root Device.
[245090.516713] audit: type=1131 audit(1706268588.770:23428): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Stopped Create Static Device Nodes in /dev.
[245090.544717] audit: type=1131 audit(1706268588.798:23429): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Stopped Device-Mapper Multipath Device Controller.
[245090.575750] audit: type=1131 audit(1706268588.829:23430): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=multipathd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Reached target System Shutdown.
[ OK ] Reached target Late Shutdown Services.
[ OK ] Finished System Reboot.
[245090.619726] audit: type=1130 audit(1706268588.873:23431): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-reboot comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[245090.639307] audit: type=1131 audit(1706268588.873:23432): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-reboot comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[ OK ] Reached target System Reboot.
[245090.672034] audit: type=1334 audit(1706268588.925:23433): prog-id=60 op=UNLOAD
[245090.679574] audit: type=1334 audit(1706268588.925:23434): prog-id=59 op=UNLOAD
[245090.687105] audit: type=1334 audit(1706268588.927:23435): prog-id=63 op=UNLOAD
[245120.718949] systemd-shutdown[1]: Syncing filesystems and block devices - timed out, issuing SIGKILL to PID 3377584.
[245120.730995] systemd-journald[2863]: Failed to send WATCHDOG=1 notification message: Connection refused
[245120.774387] systemd-journald[2863]: Received SIGTERM from PID 1 (systemd-shutdow).
[245130.775151] systemd-shutdown[1]: Waiting for process: 3377515 (umount), 3377584 ((sd-sync))
[245210.836634] systemd-shutdown[1]: Sending SIGKILL to PID 3377515 (umount).
[245210.857197] systemd-shutdown[1]: Sending SIGKILL to PID 3377584 ((sd-sync)).
[245220.880927] systemd-shutdown[1]: Waiting for process: 3377515 (umount), 3377584 ((sd-sync))
[245280.135213] INFO: task (sd-sync):3377584 blocked for more than 122 seconds.
[245280.155688] Tainted: G S 6.6.14 #1
[245280.174708] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[245280.195957] task:(sd-sync) state:D stack:0 pid:3377584 ppid:1 flags:0x00004006
[245280.217641] Call Trace:
[245280.233200] <TASK>
[245280.247885] __schedule+0x1f6/0x620
[245280.263760] ? __dequeue_entity+0x180/0x300
[245280.281073] schedule+0x57/0xa0
[245280.296612] schedule_preempt_disabled+0x11/0x20
[245280.313110] rwsem_down_read_slowpath+0x291/0x4e0
[245280.329497] ? __x64_sys_tee+0xd0/0xd0
[245280.345413] down_read+0x44/0xb0
[245280.359925] super_lock+0xcc/0x130
[245280.375582] ? sync_inodes_sb+0xd3/0x100
[245280.390454] ? __x64_sys_tee+0xd0/0xd0
[245280.404744] iterate_supers+0x62/0xe0
[245280.418801] ksys_sync+0x40/0xa0
[245280.433018] __do_sys_sync+0xa/0x20
[245280.447150] do_syscall_64+0x5c/0x90
[245280.460638] ? srso_return_thunk+0x5/0x10
[245280.474983] ? do_user_addr_fault+0x2fd/0x640
[245280.489355] ? srso_return_thunk+0x5/0x10
[245280.502839] ? exc_page_fault+0x63/0x120
[245280.516142] entry_SYSCALL_64_after_hwframe+0x4b/0xb5
[245280.530250] RIP: 0033:0x7febd8a3ed5b
[245280.542443] RSP: 002b:00007ffe0280ea08 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2
[245280.559435] RAX: ffffffffffffffda RBX: 00007ffe02810fcc RCX: 00007febd8a3ed5b
[245280.575104] RDX: 00000000ffffffff RSI: 00000000ffffffff RDI: 0000000000000003
[245280.592188] RBP: 00007ffe0280eb20 R08: 00007ffe0280e7f0 R09: 0000000000000000
[245280.608226] R10: 0000000000000008 R11: 0000000000000246 R12: 00007ffe0280ee48
[245280.623019] R13: 000055e7fda6f140 R14: 0000000000000000 R15: 0000000000000000
[245280.638562] </TASK>
[245301.077808] EXT4-fs (sda3): re-mounted 38605174-d6c8-40e2-b628-10fb44e56ad6 ro. Quota mode: disabled.
[245301.279974] systemd-shutdown[1]: Could not stop MD /dev/md127: Device or resource busy
[245301.294865] watchdog: watchdog0: watchdog did not stop!
[245301.317576] systemd-shutdown[1]: Failed to finalize MD devices, ignoring.
[245331.332314] systemd-shutdown[1]: Syncing filesystems and block devices - timed out, issuing SIGKILL to PID 3377598.
[245332.365854] sd 10:0:1:0: [sdf] Synchronizing SCSI cache
[245332.378113] sd 10:0:0:0: [sde] Synchronizing SCSI cache
[245332.390100] sd 9:0:1:0: [sdd] Synchronizing SCSI cache
[245332.401820] sd 9:0:0:0: [sdc] Synchronizing SCSI cache
[245332.414480] mlx5_core 0000:e2:00.1: Shutdown was called
[245332.428515] mlx5_core 0000:e2:00.0: Shutdown was called
[245332.443713] mpt3sas_cm1: sending message unit reset !!
[245332.458326] mpt3sas_cm1: message unit reset: SUCCESS
[245332.472327] mlx5_core 0000:81:00.1: Shutdown was called
[245332.485930] mlx5_core 0000:81:00.0: Shutdown was called
[245333.328620] mpt3sas_cm0: sending message unit reset !!
[245333.342325] mpt3sas_cm0: message unit reset: SUCCESS
[245333.371874] mlx5_core 0000:25:00.1: Shutdown was called
[245333.384863] mlx5_core 0000:25:00.0: Shutdown was called
[245333.511067] bond4: (slave eno33np0): link status definitely down, disabling slave
[245333.524258] bond4: (slave eno34np1): link status definitely down, disabling slave
[245333.537324] bond4: now running without any active interface!
[245333.552890] bond1: (slave eno35np2): link status definitely down, disabling slave
[245333.566228] bond1: (slave eno36np3): link status definitely down, disabling slave
[245338.903547] EXT4-fs (md127): unmounting filesystem 37da47ff-5fca-4f3b-b51d-9bd61b3afed2.
[245344.542628] megaraid_sas 0000:01:00.0: megasas_disable_intr_fusion is called outbound_intr_mask:0x40000009
[245344.562116] ACPI: PM: Preparing to enter system sleep state S5
[245344.574302] reboot: Restarting system
[245344.584193] reboot: machine restart
After system comes up journalctl reports this:
Jan 26 11:26:48 systemd[1]: mnt-u2.mount: Unmounting timed out. Terminating.
Jan 26 11:28:18 systemd[1]: mnt-u2.mount: Mount process timed out. Killing.
Jan 26 11:28:18 systemd[1]: mnt-u2.mount: Killing process 3377515 (umount) with signal SIGKILL.
Jan 26 11:29:48 systemd[1]: mnt-u2.mount: Mount process still around after SIGKILL. Ignoring.
Jan 26 11:29:48 systemd[1]: mnt-u2.mount: Failed with result 'timeout'.
Confused here since it stated on serial console output
[ OK ] Unmounted /mnt/u2.
Later on systemd-shutdown does then see something is wrong:
[245120.718949] systemd-shutdown[1]: Syncing filesystems and block devices - timed out, issuing SIGKILL to PID 3377584.
.
.
[245130.775151] systemd-shutdown[1]: Waiting for process: 3377515 (umount), 3377584 ((sd-sync))
[245210.836634] systemd-shutdown[1]: Sending SIGKILL to PID 3377515 (umount).
[245210.857197] systemd-shutdown[1]: Sending SIGKILL to PID 3377584 ((sd-sync)).
[245220.880927] systemd-shutdown[1]: Waiting for process: 3377515 (umount), 3377584 ((sd-sync))
.
.
The only way I can get the system to reboot properly is when sending the
following command before doing the reboot:
echo 1 > /proc/sys/vm/drop_caches
Is it possible to tell systemd-shutdown to wait longer or are there
some other parameters I need to tune?
This is systemd-252-18.el9.x86_64 with kernel 6.6.14. /mnt/u2 is an ext4
filesystem on a software raid0 over 4 NVME devices. Distribution is
AlmaLinux 9.3
Regards,
Holger
More information about the systemd-devel
mailing list