You are not logged in.
Recently I noticed that after updating my system (sudo pacman -Syu) when the post install task (reloading system manager configuration...) ran that there was a noticeable delay of over 1 minute. I determined that this pacman hook called systemctl daemon-reload and if I ran this I got the same delay. I also noticed the same delay if I ran either enable or disable. For example:
[root@spike ~]# time systemctl disable postgresql.service
Removed "/etc/systemd/system/multi-user.target.wants/postgresql.service".
real 1m0.507s
user 0m0.009s
sys 0m0.004s
[root@spike ~]# time systemctl enable postgresql.service
Created symlink /etc/systemd/system/multi-user.target.wants/postgresql.service -> /usr/lib/systemd/system/postgresql.service.
real 1m0.254s
user 0m0.004s
sys 0m0.009
In both cases the message was displayed immediately. I could not find anything with journalctl. Any ideas?
Last edited by eda2z (2022-11-28 20:14:54)
Offline
Systemd has been updated. As a core component it probably needs a reboot to finish properly.
Also check that '/etc/mkinitcpio.conf.pacnew' is solved (don't forget to regenerate initramfs).
Last edited by Maniaxx (2022-11-26 20:35:13)
sys2064
Offline
Thanks but it made no difference. My system was updated but I still regenerated initramfs. Some other weirdness - I have a laptop which has the same packages installed and it does not exhibit the problem; and when the system is hanging on an enable/disable I can open another terminal window (Gnome) but I cannot even enter "ls" in the window.
Offline
Maybe do a fsck on the drive.
What happens when you create the link manually?
Check the drive/filesystem for free space (especially free inodes).
Last edited by Maniaxx (2022-11-27 00:36:57)
sys2064
Offline
I could not find anything with journalctl. Any ideas?
In that case, only if you are not both an expert and infallible would it be worthwhile to post the journal.
People are likely to have more ideas if you provide them with the information. Presumably, you're asking because you hope somebody will spot something you haven't. The less you provide, the less there is to spot.
Last edited by cfr (2022-11-27 04:02:31)
CLI Paste | How To Ask Questions
Arch Linux | x86_64 | GPT | EFI boot | refind | stub loader | systemd | LVM2 on LUKS
Lenovo x270 | Intel(R) Core(TM) i5-7200U CPU @ 2.50GHz | Intel Wireless 8265/8275 | US keyboard w/ Euro | 512G NVMe INTEL SSDPEKKF512G7L
Offline
fsck on the drive showed no errors.
creation and removal of the link returns instantly.
free space on the drive looks good:
[ed@spike ~]$ stat -f /dev/nvme0n1p2
File: "/dev/nvme0n1p2"
ID: aded86dbe1adc2f1 Namelen: 255 Type: tmpfs
Block size: 4096 Fundamental block size: 4096
Blocks: Total: 2007883 Free: 2007883 Available: 2007883
Inodes: Total: 2007883 Free: 2007270
If I re-run the tests:
[root@spike ~]# date
Sun Nov 27 09:15:48 AM CST 2022
[root@spike ~]# time systemctl disable postgresql.service
Removed "/etc/systemd/system/multi-user.target.wants/postgresql.service".
real 1m0.424s
user 0m0.006s
sys 0m0.009s
[root@spike ~]# time systemctl enable postgresql.service
Created symlink /etc/systemd/system/multi-user.target.wants/postgresql.service -> /usr/lib/systemd/system/postgresql.service.
real 1m0.325s
user 0m0.012s
sys 0m0.003s
[root@spike ~]# date
Sun Nov 27 09:18:13 AM CST 2022
I get the following journal for that time period:
Nov 27 09:15:35 spike gnome-character[1736]: JS LOG: Characters Application exiting
Nov 27 09:15:42 spike audit[2215]: USER_AUTH pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike audit[2215]: USER_ACCT pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike su[2215]: (to root) ed on pts/0
Nov 27 09:15:42 spike kernel: audit: type=1100 audit(1669562142.728:100): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike kernel: audit: type=1101 audit(1669562142.728:101): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike kernel: audit: type=1103 audit(1669562142.728:102): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike kernel: audit: type=1105 audit(1669562142.728:103): pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike audit[2215]: CRED_ACQ pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike audit[2215]: USER_START pid=2215 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/0 res=success'
Nov 27 09:15:42 spike su[2215]: pam_unix(su-l:session): session opened for user root(uid=0) by (uid=1000)
Nov 27 09:15:47 spike systemd[1]: systemd-localed.service: Deactivated successfully.
Nov 27 09:15:47 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-localed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:47 spike kernel: audit: type=1131 audit(1669562147.344:104): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-localed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:47 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike kernel: audit: type=1334 audit(1669562147.448:105): prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike kernel: audit: type=1334 audit(1669562147.448:106): prog-id=0 op=UNLOAD
Nov 27 09:15:47 spike kernel: audit: type=1334 audit(1669562147.448:107): prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Nov 27 09:15:54 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:54 spike kernel: audit: type=1131 audit(1669562154.598:108): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:54 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike kernel: audit: type=1334 audit(1669562154.694:109): prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike kernel: audit: type=1334 audit(1669562154.694:110): prog-id=0 op=UNLOAD
Nov 27 09:15:54 spike kernel: audit: type=1334 audit(1669562154.694:111): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike systemd[1]: systemd-timedated.service: Deactivated successfully.
Nov 27 09:15:55 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timedated comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:55 spike kernel: audit: type=1131 audit(1669562155.441:112): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timedated comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:15:55 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike kernel: audit: type=1334 audit(1669562155.478:113): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike kernel: audit: type=1334 audit(1669562155.478:114): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike kernel: audit: type=1334 audit(1669562155.478:115): prog-id=0 op=UNLOAD
Nov 27 09:15:55 spike systemd-timesyncd[476]: Contacted time server 209.51.161.238:123 (0.arch.pool.ntp.org).
Nov 27 09:15:55 spike systemd-timesyncd[476]: Initial clock synchronization to Sun 2022-11-27 09:15:55.985275 CST.
Nov 27 09:15:57 spike systemd[1]: Reloading.
Nov 27 09:16:58 spike audit: BPF prog-id=31 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.370:116): prog-id=31 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.370:117): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=32 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=33 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=34 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=35 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=36 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=37 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:118): prog-id=32 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:119): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:120): prog-id=33 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:121): prog-id=34 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:122): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:123): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:124): prog-id=35 op=LOAD
Nov 27 09:16:58 spike kernel: audit: type=1334 audit(1669562218.373:125): prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=38 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=39 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=40 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=41 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=42 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=43 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=44 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=45 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:16:58 spike audit: BPF prog-id=46 op=LOAD
Nov 27 09:16:58 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:17:02 spike systemd[1]: libvirtd.service: Deactivated successfully.
Nov 27 09:17:01 spike audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=libvirtd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 27 09:17:08 spike systemd[1]: Reloading.
Nov 27 09:18:09 spike audit: BPF prog-id=47 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=48 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=49 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=50 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=51 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: kauditd_printk_skb: 23 callbacks suppressed
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:149): prog-id=47 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:150): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:151): prog-id=48 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:152): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:153): prog-id=49 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:154): prog-id=50 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:155): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:156): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:157): prog-id=51 op=LOAD
Nov 27 09:18:09 spike kernel: audit: type=1334 audit(1669562289.119:158): prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=52 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=53 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=54 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=55 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=56 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=57 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=58 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=59 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=60 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=61 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:09 spike audit: BPF prog-id=62 op=LOAD
Nov 27 09:18:09 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:18:32 spike systemd[951]: Started Application launched by gnome-shell.
Nov 27 09:18:33 spike systemd[951]: Started VTE child process 2320 launched by gnome-terminal-server process 1747.
Nov 27 09:19:05 spike dbus-daemon[968]: [session uid=1000 pid=968] Activating via systemd: service name='org.freedesktop.Tracker3.Miner.Extract' unit='tracker-extract-3.service' requested by ':1.71' (uid=1000 pid=1766 comm="/usr/lib/tracker-miner-fs-3")
Nov 27 09:19:05 spike systemd[951]: Starting Tracker metadata extractor...
Nov 27 09:19:05 spike dbus-daemon[968]: [session uid=1000 pid=968] Successfully activated service 'org.freedesktop.Tracker3.Miner.Extract'
Nov 27 09:19:05 spike systemd[951]: Started Tracker metadata extractor.
Nov 27 09:19:16 spike audit[2524]: USER_AUTH pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: kauditd_printk_skb: 22 callbacks suppressed
Nov 27 09:19:16 spike kernel: audit: type=1100 audit(1669562356.186:181): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:authentication grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: audit: type=1101 audit(1669562356.186:182): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: audit: type=1103 audit(1669562356.189:183): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike kernel: audit: type=1105 audit(1669562356.189:184): pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike audit[2524]: USER_ACCT pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike audit[2524]: CRED_ACQ pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike audit[2524]: USER_START pid=2524 uid=1000 auid=1000 ses=4 msg='op=PAM:session_open grantors=pam_unix acct="root" exe="/usr/bin/su" hostname=? addr=? terminal=/dev/pts/1 res=success'
Nov 27 09:19:16 spike su[2524]: (to root) ed on pts/1
Nov 27 09:19:16 spike su[2524]: pam_unix(su-l:session): session opened for user root(uid=0) by (uid=1000)
Nov 27 09:21:02 spike systemd[1]: Reloading.
Nov 27 09:22:03 spike audit: BPF prog-id=63 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=64 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=65 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:185): prog-id=63 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:186): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:187): prog-id=64 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:188): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.121:189): prog-id=65 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:190): prog-id=66 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:191): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:192): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=66 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=67 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=68 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=69 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=70 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:193): prog-id=67 op=LOAD
Nov 27 09:22:03 spike kernel: audit: type=1334 audit(1669562523.124:194): prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=71 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=72 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=73 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=74 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=75 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=76 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=77 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Nov 27 09:22:03 spike audit: BPF prog-id=78 op=LOAD
Nov 27 09:22:03 spike audit: BPF prog-id=0 op=UNLOAD
Offline
free space on the drive looks good:
[ed@spike ~]$ stat -f /dev/nvme0n1p2 File: "/dev/nvme0n1p2" ID: aded86dbe1adc2f1 Namelen: 255 Type: tmpfs Block size: 4096 Fundamental block size: 4096 Blocks: Total: 2007883 Free: 2007883 Available: 2007883 Inodes: Total: 2007883 Free: 2007270
Read that output again. You can see it isn't telling you anything about your root partition: *all* of the blocks are free and the file system type is tmpfs.
df -h
lsblk -f
will tell you how much space you have, though I don't think it will report inodes.
The journal snippet you posted shows nothing about manipulating the postgresql.service.
Last edited by cfr (2022-11-27 23:32:38)
CLI Paste | How To Ask Questions
Arch Linux | x86_64 | GPT | EFI boot | refind | stub loader | systemd | LVM2 on LUKS
Lenovo x270 | Intel(R) Core(TM) i5-7200U CPU @ 2.50GHz | Intel Wireless 8265/8275 | US keyboard w/ Euro | 512G NVMe INTEL SSDPEKKF512G7L
Offline
free space and inode info:
root@spike ~]# df -h
Filesystem Size Used Avail Use% Mounted on
dev 7.7G 0 7.7G 0% /dev
run 7.7G 1.9M 7.7G 1% /run
/dev/nvme0n1p2 468G 141G 304G 32% /
tmpfs 7.7G 183M 7.6G 3% /dev/shm
tmpfs 7.7G 2.2M 7.7G 1% /tmp
/dev/sdb1 916G 363G 507G 42% /mnt/xdrive
/dev/sda1 916G 251G 620G 29% /spare
/dev/nvme0n1p1 746M 52M 695M 7% /efi
tmpfs 1.6G 72K 1.6G 1% /run/user/1000
[root@spike ~]# df -ih
Filesystem Inodes IUsed IFree IUse% Mounted on
dev 2.0M 613 2.0M 1% /dev
run 2.0M 1.1K 2.0M 1% /run
/dev/nvme0n1p2 30M 633K 30M 3% /
tmpfs 2.0M 845 2.0M 1% /dev/shm
tmpfs 1.0M 40 1.0M 1% /tmp
/dev/sdb1 59M 323K 58M 1% /mnt/xdrive
/dev/sda1 59M 85K 59M 1% /spare
/dev/nvme0n1p1 0 0 0 - /efi
tmpfs 394K 115 394K 1% /run/user/1000
[root@spike ~]# lsblk -f
NAME FSTYPE FSVER LABEL UUID FSAVAIL FSUSE% MOUNTPOINTS
sda
└─sda1 ext4 1.0 ea8cb5f3-1cee-45ea-857c-da18d070ccd5 619G 27% /spare
sdb
└─sdb1 ext4 1.0 MyBook dbf35e43-9443-4931-afd4-39bd32aef8b3 506.5G 40% /mnt/xdrive
sr0
nvme0n1
├─nvme0n1p1 vfat FAT32 ESP 1455-F4BB 694.1M 7% /efi
└─nvme0n1p2 ext4 1.0 165f0ea0-97d7-4e1e-9756-c1f01c099c38 303.5G 30% /
postgresql specific journal entries for today:
[root@spike ~]# journalctl -S today -u postgresql.service
Nov 27 08:45:24 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.137 CST [556] LOG: received fast shutdown request
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.144 CST [556] LOG: aborting any active transactions
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.150 CST [556] LOG: background worker "logical replication launcher" (PID 606) exited with exit code 1
Nov 27 08:45:24 spike postgres[601]: 2022-11-27 08:45:24.150 CST [601] LOG: shutting down
Nov 27 08:45:24 spike postgres[556]: 2022-11-27 08:45:24.196 CST [556] LOG: database system is shut down
Nov 27 08:45:24 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 08:45:24 spike systemd[1]: Stopped PostgreSQL database server.
Nov 27 08:45:24 spike systemd[1]: postgresql.service: Consumed 22.039s CPU time.
-- Boot daa53010c29b4192b71957cbfba1b335 --
Nov 27 08:50:36 spike systemd[1]: Starting PostgreSQL database server...
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.483 CST [547] LOG: starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.2.0, 64-bit
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.485 CST [547] LOG: listening on IPv6 address "::1", port 5432
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.485 CST [547] LOG: listening on IPv4 address "127.0.0.1", port 5432
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.490 CST [547] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Nov 27 08:50:36 spike postgres[592]: 2022-11-27 08:50:36.503 CST [592] LOG: database system was shut down at 2022-11-27 08:45:24 CST
Nov 27 08:50:36 spike postgres[547]: 2022-11-27 08:50:36.513 CST [547] LOG: database system is ready to accept connections
Nov 27 08:50:36 spike systemd[1]: Started PostgreSQL database server.
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.003 CST [547] LOG: received fast shutdown request
Nov 27 09:14:16 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.007 CST [547] LOG: aborting any active transactions
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.009 CST [547] LOG: background worker "logical replication launcher" (PID 602) exited with exit code 1
Nov 27 09:14:16 spike postgres[597]: 2022-11-27 09:14:16.013 CST [597] LOG: shutting down
Nov 27 09:14:16 spike postgres[547]: 2022-11-27 09:14:16.056 CST [547] LOG: database system is shut down
Nov 27 09:14:16 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 09:14:16 spike systemd[1]: Stopped PostgreSQL database server.
-- Boot 1ee61d59969f4531b03a0d4d6abfaab4 --
Nov 27 09:15:02 spike systemd[1]: Starting PostgreSQL database server...
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.392 CST [546] LOG: starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.2.0, 64-bit
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.395 CST [546] LOG: listening on IPv6 address "::1", port 5432
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.395 CST [546] LOG: listening on IPv4 address "127.0.0.1", port 5432
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.399 CST [546] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Nov 27 09:15:02 spike postgres[585]: 2022-11-27 09:15:02.409 CST [585] LOG: database system was shut down at 2022-11-27 09:14:16 CST
Nov 27 09:15:02 spike postgres[546]: 2022-11-27 09:15:02.419 CST [546] LOG: database system is ready to accept connections
Nov 27 09:15:02 spike systemd[1]: Started PostgreSQL database server.
Nov 27 09:25:35 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.209 CST [546] LOG: received fast shutdown request
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.213 CST [546] LOG: aborting any active transactions
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.214 CST [546] LOG: background worker "logical replication launcher" (PID 592) exited with exit code 1
Nov 27 09:25:35 spike postgres[587]: 2022-11-27 09:25:35.221 CST [587] LOG: shutting down
Nov 27 09:25:35 spike postgres[546]: 2022-11-27 09:25:35.261 CST [546] LOG: database system is shut down
Nov 27 09:25:35 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 09:25:35 spike systemd[1]: Stopped PostgreSQL database server.
-- Boot dae7d0d44d3c4304a74d5f682aac0104 --
Nov 27 09:26:21 spike systemd[1]: Starting PostgreSQL database server...
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.398 CST [563] LOG: starting PostgreSQL 14.6 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 12.2.0, 64-bit
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.400 CST [563] LOG: listening on IPv6 address "::1", port 5432
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.400 CST [563] LOG: listening on IPv4 address "127.0.0.1", port 5432
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.403 CST [563] LOG: listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
Nov 27 09:26:21 spike postgres[601]: 2022-11-27 09:26:21.415 CST [601] LOG: database system was shut down at 2022-11-27 09:25:35 CST
Nov 27 09:26:21 spike postgres[563]: 2022-11-27 09:26:21.427 CST [563] LOG: database system is ready to accept connections
Nov 27 09:26:21 spike systemd[1]: Started PostgreSQL database server.
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.427 CST [563] LOG: received fast shutdown request
Nov 27 09:28:43 spike systemd[1]: Stopping PostgreSQL database server...
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.430 CST [563] LOG: aborting any active transactions
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.431 CST [563] LOG: background worker "logical replication launcher" (PID 609) exited with exit code 1
Nov 27 09:28:43 spike postgres[604]: 2022-11-27 09:28:43.431 CST [604] LOG: shutting down
Nov 27 09:28:43 spike postgres[563]: 2022-11-27 09:28:43.465 CST [563] LOG: database system is shut down
Nov 27 09:28:43 spike systemd[1]: postgresql.service: Deactivated successfully.
Nov 27 09:28:43 spike systemd[1]: Stopped PostgreSQL database server.
If my understanding of systemctl enable/disable is correct then all it should be doing in creating and removing a link and thus there should be no journal entries for that - which there are not. Also if all systemd is doing in creating/removing a link why can I do it instantly but systemd hangs for almost a minute *after* displaying what it has done.
Offline
Try an 'strace -v -f -s 256 -o /tmp/strace.log systemctl disable postgresql.service' and post the strace.log file. Let it run for the minute until it ends properly.
sys2064
Offline
systemctl will IPC talk to the damon and we already know that the dameon-reload is the slow part.
systemctl log-level # to note the original loglevel
systemctl log-level debug
systemctl daemon-reload
systemctl log-level info # i guess
Then inspect the system journal
Also if all systemd is doing in creating/removing a link why can I do it instantly but systemd hangs for almost a minute *after* displaying what it has done.
--no-reload
When used with enable and disable, do not implicitly reload daemon configuration after
executing the changes.
Offline
The strace log can be found at: https://0x0.st/o0bY.log
And the journal for running systemctl in debug mode can be found at: https://0x0.st/o0bg.txt
Thanks for the tip about --no-reload. I tried it and enable/disable worked instantly. I definitely need to read the man pages more closely.
Offline
Nov 28 09:32:29 spike systemd[2550]: /usr/lib/systemd/system-generators/systemd-system-update-generator succeeded.
Nov 28 09:33:29 spike systemd[2550]: /usr/lib/systemd/system-generators/netplan succeeded.
Somethingsomethingnetwork.
From the debug output it looks like there're multiple network daemons:
find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
Offline
[root@spike ~]# find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
atd.service | multi-user.target.wants
bluetooth.service | bluetooth.target.wants
cups.socket | sockets.target.wants
dbus-org.bluez.service | system
dbus-org.freedesktop.nm-dispatcher.service | system
dbus-org.freedesktop.timesync1.service | system
display-manager.service | system
fstrim.timer | timers.target.wants
gcr-ssh-agent.socket | sockets.target.wants
getty@tty1.service | getty.target.wants
gnome-keyring-daemon.socket | sockets.target.wants
httpd.service | multi-user.target.wants
libvirtd-ro.socket | sockets.target.wants
libvirtd.service | multi-user.target.wants
libvirtd.socket | sockets.target.wants
lm_sensors.service | multi-user.target.wants
NetworkManager.service | multi-user.target.wants
NetworkManager-wait-online.service | network-online.target.wants
p11-kit-server.socket | sockets.target.wants
pipewire-media-session.service | pipewire.service.wants
pipewire-session-manager.service | user
pipewire.socket | sockets.target.wants
pulseaudio.socket | sockets.target.wants
qxserver.service | multi-user.target.wants
reflector.timer | timers.target.wants
remote-fs.target | multi-user.target.wants
sshd.service | multi-user.target.wants
systemd-timesyncd.service | sysinit.target.wants
virtlockd.socket | sockets.target.wants
virtlogd.socket | sockets.target.wants
xdg-user-dirs-update.service | default.target.wants
Offline
Nope.
Temporarily get rid of https://archlinux.org/packages/communit … 4/netplan/ and see what happens.
Offline
Thank you. That fixed the problem. daemon-reload returns immediately. I installed netplan to create a network bridge so that I could have my kvm guests on the same subnet as my host. It's weird since I installed netplan and created the bridge back on 9/18 but this problem only started occurring several weeks ago.
I was able to start the bridge with virsh and run a VM but I noticed that after a certain amount of time virsh showed the bridge becoming inactive by itself. I can easily do without the bridge if there is no way around it. Please let me know what you think.
Offline
netplan was updated Aug 22, 2022 - you could try to downgrade it to 0.104-1 from the ALA (or your cache)
I've never used netplan and no idea how it's related to a bridge.
https://wiki.archlinux.org/title/Network_bridge and configure your VM to use the bridge device (eg. br0), https://wiki.archlinux.org/title/Libvirt#Networking ??
Edit: either way please always remember to mark resolved threads by editing your initial posts subject - so others will know that there's no task left, but maybe a solution to find.
Thanks.
And in this case, maybe even mention the cause in the subject - netplan seems fringe (I wasn't even aware that it exists…)
Last edited by seth (2022-11-28 19:55:21)
Offline
I'll clean-up my networking setup and check into the 2 links you mentioned. I'll admit that I got lazy and googled how to get the guests on the same subnet as the host. If you're curious - https://serverfault.com/questions/10754 … s-the-host. Thanks again.
Offline
I appreciate the help on figuring out this 60s delay issue. During that 60s a lot of things are blocked, even things like loading of web pages from that server, so that delay makes server administration during business hours a real problem.
For those like me who are using Arch on a VM: I found that cloud-init pulls in netplan, so my solution was to take the static IP details in /etc/netplan/50-cloud-init.yaml and created a /etc/systemd/network/eth0.network to have all the same details in systemd format. Then I did
pacman -R cloud-init netplan
and following that there was no more 60s delay when enabling and disabling services.
Offline
I appreciate the help on figuring out this 60s delay issue. During that 60s a lot of things are blocked, even things like loading of web pages from that server, so that delay makes server administration during business hours a real problem.
For those like me who are using Arch on a VM: I found that cloud-init pulls in netplan, so my solution was to take the static IP details in /etc/netplan/50-cloud-init.yaml and created a /etc/systemd/network/eth0.network to have all the same details in systemd format. Then I did
pacman -R cloud-init netplan
and following that there was no more 60s delay when enabling and disabling services.
Baah, that's it damned. Where can i get my lifetime back?
-> https://gitlab.archlinux.org/archlinux/ … issues/156
Offline
Hello, I had the same problem. In my case, netplan was installed by cloud-init(https://cloud-init.io/) with a dependency. In fact, my arch was installed by OVH and apparently they use cloud-init to configure it. I uninstalled cloud-init and that solved my problem. yay -rns cloud-init. thank for this post.
Offline