[Bug 1902427] [NEW] systemd pauses for unspecified reason

[ralphb]

Public bug reported:

I recently installed Kubuntu 20.04 on a new Ryzen 3900X system. I
noticed that the boot time (time between entering LUKS credentials and
appearance of login screen) took more than 1 minute.

Using `systemd-analyze`, I found the following:

```
cassiopeia:~# systemd-analyze 
Startup finished in 24.819s (kernel) + 1min 32.150s (userspace) = 1min 56.969s 
graphical.target reached after 1min 32.144s in userspace
cassiopeia:~# systemd-analyze blame
4.721s fstrim.service                       
2.949s apt-daily-upgrade.service            
2.380s systemd-cryptsetup at store.service     
1.739s NetworkManager-wait-online.service   
 439ms apt-daily.service                    
 421ms man-db.service                       
 398ms systemd-logind.service               
 323ms dev-mapper-root.device               
 294ms systemd-fsck at dev-mapper-store.service
 204ms logrotate.service                    
 153ms systemd-journald.service             
...
cassiopeia:~# 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 @1min 32.144s
└─multi-user.target @1min 32.144s
  └─fetchmail.service @1min 32.128s +16ms
    └─network-online.target @1min 32.127s
      └─NetworkManager-wait-online.service @1min 30.388s +1.739s
        └─NetworkManager.service @1min 30.282s +105ms
          └─dbus.service @1min 30.279s
            └─basic.target @1min 30.265s
              └─sockets.target @1min 30.265s
                └─snapd.socket @1min 30.264s +370us
                  └─sysinit.target @1min 30.262s
                    └─systemd-timesyncd.service @1min 30.219s +42ms
                      └─systemd-tmpfiles-setup.service @1min 30.202s +15ms
                        └─systemd-journal-flush.service @288ms +49ms
                          └─systemd-journald.service @131ms +153ms
                            └─systemd-journald.socket @129ms
                              └─-.mount @127ms
                                └─blockdev at dev-mapper-root.target @410ms
                                  └─systemd-cryptsetup at root.service @401ms +8ms
                                    └─dev-nvme0n1p2.device @398ms
```

This didn't really help, but `systemd-analyze plot > boot.svg` produced
an SVG file (see attachment) that shows a gap between store.mount
(completes within 38 ms) and apparmor.service of almost 1:30 minutes.
What did systemd do during this gap?

I think it is either a bug in systemd that idles, or in systemd-analyze
that doesn't disclose the actions in that gap.

(Note: I have posted this question in two well-known Ubuntu forums, but
I didn't receive any answers.)

** Affects: systemd (Ubuntu)
     Importance: Undecided
         Status: New

** Attachment added: "boot.svg"
   https://bugs.launchpad.net/bugs/1902427/+attachment/5429998/+files/boot.svg

** Package changed: snapd (Ubuntu) => systemd (Ubuntu)

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to systemd in Ubuntu.
https://bugs.launchpad.net/bugs/1902427

Title:
  systemd pauses for unspecified reason

Status in systemd package in Ubuntu:
  New

Bug description:
  I recently installed Kubuntu 20.04 on a new Ryzen 3900X system. I
  noticed that the boot time (time between entering LUKS credentials and
  appearance of login screen) took more than 1 minute.

  Using `systemd-analyze`, I found the following:

  ```
  cassiopeia:~# systemd-analyze 
  Startup finished in 24.819s (kernel) + 1min 32.150s (userspace) = 1min 56.969s 
  graphical.target reached after 1min 32.144s in userspace
  cassiopeia:~# systemd-analyze blame
  4.721s fstrim.service                       
  2.949s apt-daily-upgrade.service            
  2.380s systemd-cryptsetup at store.service     
  1.739s NetworkManager-wait-online.service   
   439ms apt-daily.service                    
   421ms man-db.service                       
   398ms systemd-logind.service               
   323ms dev-mapper-root.device               
   294ms systemd-fsck at dev-mapper-store.service
   204ms logrotate.service                    
   153ms systemd-journald.service             
  ...
  cassiopeia:~# 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 @1min 32.144s
  └─multi-user.target @1min 32.144s
    └─fetchmail.service @1min 32.128s +16ms
      └─network-online.target @1min 32.127s
        └─NetworkManager-wait-online.service @1min 30.388s +1.739s
          └─NetworkManager.service @1min 30.282s +105ms
            └─dbus.service @1min 30.279s
              └─basic.target @1min 30.265s
                └─sockets.target @1min 30.265s
                  └─snapd.socket @1min 30.264s +370us
                    └─sysinit.target @1min 30.262s
                      └─systemd-timesyncd.service @1min 30.219s +42ms
                        └─systemd-tmpfiles-setup.service @1min 30.202s +15ms
                          └─systemd-journal-flush.service @288ms +49ms
                            └─systemd-journald.service @131ms +153ms
                              └─systemd-journald.socket @129ms
                                └─-.mount @127ms
                                  └─blockdev at dev-mapper-root.target @410ms
                                    └─systemd-cryptsetup at root.service @401ms +8ms
                                      └─dev-nvme0n1p2.device @398ms
  ```

  This didn't really help, but `systemd-analyze plot > boot.svg`
  produced an SVG file (see attachment) that shows a gap between
  store.mount (completes within 38 ms) and apparmor.service of almost
  1:30 minutes. What did systemd do during this gap?

  I think it is either a bug in systemd that idles, or in systemd-
  analyze that doesn't disclose the actions in that gap.

  (Note: I have posted this question in two well-known Ubuntu forums,
  but I didn't receive any answers.)

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1902427/+subscriptions