Long boot time after yesterdays update

yesterday I updated my PC. It was running over night and this morning I rebooted. The reboot took almost 2 minutes.

In the log I found these messages:

Mär 16 07:18:16 rakete systemd[1]: systemd-logind.service: Unexpected error response from GetNameOwner(): Connection terminated
Mär 16 07:18:16 rakete systemd[1]: lightdm.service: Unexpected error response from GetNameOwner(): Connection terminated
Mär 16 07:18:16 rakete systemd[1]: iwd.service: Unexpected error response from GetNameOwner(): Connection terminated
Mär 16 07:18:16 rakete systemd[1]: avahi-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Mär 16 07:18:16 rakete systemd[1]: colord.service: Unexpected error response from GetNameOwner(): Connection terminated
Mär 16 07:18:16 rakete systemd[1]: accounts-daemon.service: Unexpected error response from GetNameOwner(): Connection terminated
Mär 16 07:18:16 rakete systemd[1]: polkit.service: Unexpected error response from GetNameOwner(): Connection terminated

I never had that before. Seems to be related to this upgrade

[2021-03-15T17:31:42+0100] [ALPM] upgraded systemd (247.3-1 -> 247.4-2)

There is an issue on github from Nov. 2020 describing the problem and giving the solution that worked for me (https://github.com/systemd/systemd/issues/15316):

sudo pacman -S dbus-broker
sudo systemctl enable dbus-broker.service
sudo systemctl --global enable dbus-broker.service
2 Likes

let’s see if it happens here too:
2021-03-16_12-53

No issue here:

[13:08:26] joekamprad :: Ungeheuer64  ➜  ~ » systemd-analyze critical-chain
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @2.863s
└─multi-user.target @2.863s
  └─systemd-user-sessions.service @1.441s +7ms
    └─nss-user-lookup.target @1.474s

Do you also use systemd-swap ? If have read a comment that this could be related.

Can you test with systemd-swap activated?

Since my installation was in the same state as far as updating is concerned. I ran a test before and after:

Before Update: 

[elloquin@elloquin ~]$ checkupdates
eos-bash-shared 1.6-1 -> 1.6.1-1
ffmpeg 2:4.3.2-1 -> 2:4.3.2-2
gnome-online-accounts 3.38.0-1 -> 3.38.1-1
gtk3 1:3.24.27-3 -> 1:3.24.27-4
sqlite 3.35.0-1 -> 3.35.1-1
sudo 1.9.5.p2-1 -> 1.9.6.p1-1
systemd 247.3-1 -> 247.4-2
systemd-libs 247.3-1 -> 247.4-2
systemd-sysvcompat 247.3-1 -> 247.4-2
welcome 3.9.12-1 -> 3.10.1-1
wpebackend-fdo 1.8.0-1 -> 1.8.1-1
[elloquin@elloquin ~]$ 


[elloquin@elloquin ~]$ systemd-analyze critical-chain
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @11.707s
└─lightdm.service @10.748s +958ms
  └─systemd-user-sessions.service @10.730s +15ms
    └─nss-user-lookup.target @11.851s
[elloquin@elloquin ~]$ 

After Update:
[elloquin@elloquin ~]$ systemd-analyze critical-chain
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @12.234s
└─lightdm.service @11.370s +863ms
  └─systemd-user-sessions.service @11.358s +8ms
    └─nss-user-lookup.target @12.410s
[elloquin@elloquin ~]$

So slightly slower but negligible TBH.

i can test this in VM yes, not on my working system;)

2021-03-16_14-22
left after enable dbus-broker and right before that… not a difference and also no issue to boot with systemd-swap after latest systemd-update.

1 Like

Since the arch wiki states systemd-swap works with existing swap files (which I have on this install) I went ahead and installed and enabled it. After reboot no adverse effect. This is a dual core amd with 4 gib ram and old hardware-bare metal install. Again slower because of the now enabled sytemd-swap.service but no where near minutes of time:

[elloquin@elloquin ~]$ systemd-analyze critical-chain
The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @16.307s
└─multi-user.target @16.307s
  └─systemd-swap.service @11.207s +5.098s
    └─basic.target @11.189s
      └─sockets.target @11.189s
        └─dbus.socket @11.189s
          └─sysinit.target @11.124s
            └─systemd-update-done.service @11.100s +24ms
              └─ldconfig.service @9.975s +1.122s
                └─local-fs.target @9.973s
                  └─boot-efi.mount @9.869s +103ms
                    └─systemd-fsck@dev-disk-by\x2duuid-1B08\x2dCC7F.service @8.964s +886ms
                      └─local-fs-pre.target @8.961s
                        └─lvm2-monitor.service @2.592s +6.368s
                          └─systemd-journald.socket @2.582s
                            └─system.slice @2.471s
                              └─-.slice @2.471s
[elloquin@elloquin ~]$ 
1 Like

I did some tests and verified that it is related to systemd-swap.service. Specifically to zram.

With these settings:

zram_enabled=1
zram_size=$(( RAM_SIZE / 8 ))
zram_count=${NCPU}
zram_alg=lz4

It creates 16 zram devices each 502,6 MB and it takes

48.988s systemd-swap.service

If I change the settings to zram_count=1, which creates just one zram devices of size 7,9 GB the time is just:

1.622s systemd-swap.service

With dbus-broker.service enabled I do not have the delay with the many zram devices. And this is new behavior since today. systemd-swap package did not change since 3. January.

For now I leave dbus-broker.service disabled and just use one zram device. But I am really curious what is causing this issue.

Mine is pretty fast. All in ms.

[ricklinux@eos-plasma ~]$ systemd-analyze critical-chain
The time when unit became active or started is printed after the “@” character.
The time the unit took to start is printed after the “+” character.

graphical.target @789ms
└─sddm.service @789ms
  └─systemd-user-sessions.service @785ms +3ms
    └─network.target @784ms
      └─NetworkManager.service @728ms +55ms
        └─dbus.service @726ms
          └─basic.target @725ms
            └─sockets.target @725ms
              └─dbus.socket @725ms
                └─sysinit.target @723ms
                  └─systemd-update-done.service @721ms +2ms
                    └─ldconfig.service @616ms +103ms
                      └─local-fs.target @616ms
                        └─boot-efi.mount @507ms +108ms
                          └─systemd-fsck@dev-disk-by\x2duuid-D9A5\x2d4C5D.service @487ms +19ms
                            └─local-fs-pre.target @486ms
                              └─lvm2-monitor.service @242ms +243ms
                                └─systemd-journald.socket @239ms
                                  └─-.mount @225ms
                                    └─-.slice @225ms
[ricklinux@eos-plasma ~]$