Re: [systemd-devel] [systemd-219] Journal spamming by umount / high CPU usage
Lennart Poettering lenn...@poettering.net schrieb: To me it looks like the automounter tries to unmount unless there's still references open in the filesystem. It does, however, no try to do this after some timeout - which is fine. OTOH, this could be just an effect of the mount point forcibly vanishing because the USB device disconnected. The kernel actually allows unmounting of mounts at any time, even if the backing device has vanished. (In fact, it particularly allows unmounting in that case...) I had this case again. Since I wasn't booted with log_level=debug I simply turned the drive off, and now it gets intersting: Apr 04 16:25:26 jupiter umount[3678]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3684]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3803]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3815]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3817]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3845]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3883]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3905]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3938]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd-journal[436]: Suppressed 47447 messages from /user.slice/user-500.slice Apr 04 16:25:26 jupiter umount[3941]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount process exited, code=exited status=1 Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount is bound to inactive unit. Stopping, too. Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup... Apr 04 16:25:26 jupiter umount[3943]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount process exited, code=exited status=1 Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount is bound to inactive unit. Stopping, too. Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup... Apr 04 16:25:26 jupiter umount[3945]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount process exited, code=exited status=1 Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount is bound to inactive unit. Stopping, too. Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup... Apr 04 16:25:26 jupiter umount[3947]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount process exited, code=exited status=1 Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount is bound to inactive unit. Stopping, too. Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup... Apr 04 16:25:26 jupiter umount[3948]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt [...repeated a few times...] Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup... Apr 04 16:25:26 jupiter umount[3959]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter umount[3961]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount process exited, code=exited status=1 Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount is bound to inactive unit. Stopping, too. Apr 04 16:25:26 jupiter systemd[817]: Unmounting /mnt/private/usb-backup... Apr 04 16:25:26 jupiter umount[3963]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Apr 04 16:25:26 jupiter systemd[817]: mnt-private-usb\x2dbackup.mount mount process exited, code=exited status=1 Apr 04 16:25:26 jupiter systemd[817]: Unit mnt-private-usb\x2dbackup.mount is bound to inactive unit. Stopping, too. [...] Apr 04 16:25:26 jupiter systemd-journal[436]: Suppressed 11231 messages from /user.slice/user-500.slice Apr 04 16:25:26 jupiter systemd[817]: Failed unmounting /mnt/private/usb- backup. Apr 04 16:25:26
Re: [systemd-devel] [systemd-219] Journal spamming by umount / high CPU usage
On Sun, 29.03.15 17:12, Kai Krakow (hurikha...@gmail.com) wrote: Hello! I've got a automount point for a daily USB backup job. Due to some instabilities of early USB3 chipsets and early USB3 devices, the mounted device sometimes wents offline and eventually comes back after a while but my backup job is stuck (rsync). I configured rsync to shutdown upon block io timeouts. This in turn makes the systemd automounter think (correctly) that the mount point is no longer in use - but it cannot be unmounted. The problem here is, that it spams the journal with hundreds of messages per minute all day long (or as long as I don't reboot): Hmm? The systemd automount logic so far does not support mount expiration, hence I cannot really parse what you write above? Mär 29 16:49:00 jupiter umount[19547]: umount: /mnt/private/usb-backup: umount fehlgeschlagen: Die Operation ist nicht erlaubt Why does this fail with EPERM? I don't really follow I must admit... Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] [systemd-219] Journal spamming by umount / high CPU usage
On Thu, 02.04.15 11:11, Kai Krakow (hurikha...@gmail.com) wrote: Hi! Lennart Poettering lenn...@poettering.net schrieb am Do., 2. Apr. 2015 um 10:49 Uhr: On Sun, 29.03.15 17:12, Kai Krakow (hurikha...@gmail.com) wrote: Hello! I've got a automount point for a daily USB backup job. Due to some instabilities of early USB3 chipsets and early USB3 devices, the mounted device sometimes wents offline and eventually comes back after a while but my backup job is stuck (rsync). I configured rsync to shutdown upon block io timeouts. This in turn makes the systemd automounter think (correctly) that the mount point is no longer in use - but it cannot be unmounted. The problem here is, that it spams the journal with hundreds of messages per minute all day long (or as long as I don't reboot): Hmm? The systemd automount logic so far does not support mount expiration, hence I cannot really parse what you write above? What exactly do you mean with expiration? Expiration by time or by usage? Expiration is what the kernel autofs logic calls when a mount is detected to be idle, and then after a timeout unmounted. systemd does not support expiration right now. very recently there have been posted patches to add this, but they have not been applied yet, and hence on your system whatever you are running into is not related to thus. To me it looks like the automounter tries to unmount unless there's still references open in the filesystem. It does, however, no try to do this after some timeout - which is fine. OTOH, this could be just an effect of the mount point forcibly vanishing because the USB device disconnected. The kernel actually allows unmounting of mounts at any time, even if the backing device has vanished. (In fact, it particularly allows unmounting in that case...) Maybe this is by kernel design? The filesystem forced itself read-only (due to IO errors to an offlined/disconnected device), then went offline. The kernel probably umounted it, and I believe that now another manual umount results in EPERM, tho I cannot test that now. I can test it this evening if it is of interested. I could also test other ideas to debug if you instruct me. I am pretty sure there's something weird going on here. Any chance you can boot with systemd.log_level=debug on the kernel cmdline, then reproduce the issue and paste the output this generates here? Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] [systemd-219] Journal spamming by umount / high CPU usage
Hello!
I've got a automount point for a daily USB backup job. Due to some
instabilities of early USB3 chipsets and early USB3 devices, the mounted
device sometimes wents offline and eventually comes back after a while but
my backup job is stuck (rsync). I configured rsync to shutdown upon block io
timeouts. This in turn makes the systemd automounter think (correctly) that
the mount point is no longer in use - but it cannot be unmounted. The
problem here is, that it spams the journal with hundreds of messages per
minute all day long (or as long as I don't reboot):
Mär 29 16:49:00 jupiter umount[19547]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19575]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19577]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19645]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19671]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19719]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19795]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19843]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19853]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19907]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
Mär 29 16:49:00 jupiter umount[19947]: umount: /mnt/private/usb-backup:
umount fehlgeschlagen: Die Operation ist nicht erlaubt
The German phrase means umount failed: operation not permitted. This in
turn leads to a constant CPU usage of systemd and journald between 30% and
70% added together and the journal grows to gigabytes, meanwhile old
journals become rotated away so that I currently cannot even look back far
enough to see the logs right before that repeating incident. The system
reboots just fine, there's no hanging systemd job during shutdown.
The thing is, the device is back - it switched to another device node, tho
(sda at boot, not sdf). The systemd automounter happily mounts it when
changing to the directory, and I can list all my files fine. The backup
scratch area is dirty/incomplete as expected - but there are no file system
errors or inconsistencies.
Related dmesg log purely for informational purpose to see the incident in
chronological order, this in not about discussing a btrfs issue (and it is
not):
$ dmesg|egrep sd[af]
[2.241559] sd 6:0:0:0: [sda] 3907029164 512-byte logical blocks: (2.00
TB/1.81 TiB)
[2.241878] sd 6:0:0:0: [sda] Write Protect is off
[2.241883] sd 6:0:0:0: [sda] Mode Sense: 03 00 00 00
[2.242380] sd 6:0:0:0: [sda] No Caching mode page found
[2.242419] sd 6:0:0:0: [sda] Assuming drive cache: write through
[2.267163] sda: sda1
[2.268617] sd 6:0:0:0: [sda] Attached SCSI disk
[4.349156] BTRFS: device label usb-backup devid 1 transid 28610
/dev/sda1
# backup started here:
[13059.571377] BTRFS info (device sda1): force zlib compression
[13059.571382] BTRFS info (device sda1): disk space caching is enabled
# USB hickup here:
[58885.081027] sd 7:0:0:0: [sdf] 3907029164 512-byte logical blocks: (2.00
TB/1.81 TiB)
[58885.081433] sd 7:0:0:0: [sdf] Write Protect is off
[58885.081437] sd 7:0:0:0: [sdf] Mode Sense: 03 00 00 00
[58885.081979] sd 7:0:0:0: [sdf] No Caching mode page found
[58885.083306] sd 7:0:0:0: [sdf] Assuming drive cache: write through
# backup failed here:
[58885.250710] BTRFS: error (device sda1) in btrfs_commit_transaction:2010:
errno=-5 IO failure (Error while writing out transaction)
[58885.252190] BTRFS info (device sda1): forced readonly
[58885.252195] BTRFS warning (device sda1): Skipping commit of aborted
transaction.
[58885.252359] BTRFS: error (device sda1) in cleanup_transaction:1670:
errno=-5 IO failure
[58885.253900] BTRFS info (device sda1): delayed_refs has NO entry
[58885.253913] BTRFS error (device sda1): commit super ret -5
[58893.553877] sdf: sdf1
[58893.555061] sd 7:0:0:0: [sdf] Attached SCSI disk
# I've cd'ed into the directory here:
[99457.380783] BTRFS info (device sdf1): force zlib compression
[99457.380788] BTRFS info (device sdf1): disk space caching is enabled
Here's the configuration:
$ fgrep usb-backup /etc/fstab
LABEL=usb-backup /mnt/private/usb-backup btrfs \
noauto,noatime,compress-force=zlib,subvolid=0,x-systemd.automount \
0 0
$ systemctl cat mnt-private-usb\\x2dbackup.{automount,mount}
#
