umount fails on system with huge (2TiB) buff/cache

[Holger Kiehl <Holger.Kiehl@xxxxxx>]

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@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@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@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@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