Embarrasing boot speeds in Fedora involving LUKS partitions

I used to boast about how Fedora boots faster than Windows on my machine. Now the reverse seems to be the case. My setup includes LUKS partitions – three of them (/, /home, /swap). Looking into this with systemd-analyze, I get the following:

# systemd-analyze blame

1min 59.525s dracut-initqueue.service
27.791s firewalld.service
27.247s systemd-cryptsetup@luks\blah-blah-blah.service
27.076s systemd-cryptsetup@luks\blah-blah.service
20.742s ModemManager.service
16.949s systemd-journal-flush.service
9.322s lvm2-monitor.service
9.170s systemd-cryptsetup@luks\blah.service
8.799s systemd-udev-settle.service
8.347s NetworkManager-wait-online.service
7.704s initrd-switch-root.service
4.970s rsyslog.service
4.532s php-fpm.service
4.503s cups.service
4.026s smartd.service
3.954s avahi-daemon.service
3.879s bluetooth.service
3.563s chronyd.service
3.541s httpd.service
3.428s sysstat.service
3.414s abrtd.service
3.414s systemd-logind.service
3.410s systemd-machined.service
3.265s libvirtd.service
2.772s systemd-udevd.service
2.744s dnf-makecache.service
1.573s lm_sensors.service
1.441s sssd-kcm.service
1.179s systemd-tmpfiles-setup-dev.service
1.157s systemd-fsck@dev-disk-by\another-blah.service
988ms dbus-broker.service
` …

and
# systemd-analyze time

Startup finished in 3.997s (firmware) + 22.501s (loader) + 3.625s (kernel) + 2min 3.527s (initrd) + 1min 5.829s (userspace) = 3min 39.482s
graphical.target was never reached

3min 8secs between initrd and userspace? This is embarrasing.
How should I approach this? Which services are redundant?

About blame from man systemd-analyze:
“Note that the output might be misleading as the
initialization of one service might be slow simply because
it waits for the initialization of another service to complete.”

PS: I am live in town, thus not fear thunders, and keep my laptop suspended instead of power it off.

Two minute wait in dracut suggests a problem. I suggest filling a bug against dracut for now. Boot with parameters
rd.debug systemd.log_level=debug
and then in Terminal
sudo journalctl -b -o short-monotonic > bug#-journal.txt
then attach that txt file to the bug. Then report the bug# in this discussion thread.

1 Like

Did it be a clean install? Happened it after an updated?

Try provide also this information which can be useful:

systemd-analyze plot > boot-times.svg

dmesg

dmesg | grep -i error

journalctl -b

journalctl -b3 -p3

Maybe there are some thing that can be useful to provide a better idea about this issue.

Regards

I started off to my bugzilla account then paused to reproduce the phenomena. The outputs came out different. Take a look at these.

This one comes after booting with the suggested parameters

Second Trial
26.787s firewalld.service                                                                        
16.173s initrd-switch-root.service                                                               
14.133s lvm2-monitor.service                                                                     
14.034s systemd-cryptsetup@luks\xA07.service      
13.693s dracut-initqueue.service                                                                 
13.603s systemd-udev-settle.service                                                              
13.236s systemd-journal-flush.service                                                            
12.190s systemd-cryptsetup@luks\xA30.service  
11.986s ModemManager.service                                                                     
11.910s systemd-cryptsetup@luks\x333.service      
10.216s NetworkManager-wait-online.service                                                       
10.185s avahi-daemon.service                                                                     
10.137s bluetooth.service                                                                        
 9.548s systemd-logind.service                                                                   
 9.542s systemd-machined.service                                                                 
 9.502s abrtd.service                                                                            
 9.296s dbus-broker.service                                                                      
 4.281s smartd.service                                                                           
 4.253s polkit.service                                                                           
 3.965s httpd.service                                                                            
 3.253s libvirtd.service                                                                         
 3.071s systemd-udevd.service                                                                    
 2.878s plymouth-quit-wait.service                                                               
 2.877s plymouth-quit.service                                                                    
 2.714s php-fpm.service                                                                          
 1.959s cups.service                                                                             
 1.736s rsyslog.service                                                                          
 1.593s gssproxy.service                                                                         
 1.136s user@1000.service                                                                        
 1.047s systemd-tmpfiles-setup-dev.service                                                       
  964ms systemd-fsck@dev-disk-by\x2duuid-0266\x2dF989.service                                    
  933ms dev-mapper-luks\x333.swap                 
  916ms dracut-cmdline.service                                                                   
  804ms NetworkManager.service                                                                   
  787ms systemd-journald.service                                                                 
  755ms chronyd.service                                                                          
  632ms dev-hugepages.mount                                                                      
  630ms dev-mqueue.mount                                                                         
  629ms sys-kernel-debug.mount                                                                   
  628ms sysstat.service                                                                          
  604ms systemd-fsck@dev-disk-by\x2duuid-999.service
  599ms lm_sensors.service                                                                       
  586ms colord.service                                                                           
  584ms systemd-vconsole-setup.service                                                           
  548ms systemd-tmpfiles-setup.service                                                           
  483ms nfs-convert.service                                                                      
  467ms boot.mount                                                                               
  446ms systemd-udev-trigger.service                                                             
  442ms auditd.service                                                                           
  403ms systemd-backlight@backlight:intel_backlight.service                                      
  361ms systemd-fsck@dev-mapper-luks\xA07.service 
  317ms systemd-sysctl.service                                                                   
  309ms systemd-modules-load.service                                                             
  308ms readonly-root.service                                                                    
  303ms home.mount                                                                               
  282ms dmraid-activation.service                                                                
  280ms systemd-random-seed.service                                                              
  276ms initrd-parse-etc.service                                                                 
  221ms boot-efi.mount                                                                           
  200ms plymouth-switch-root.service                                                             
  186ms kmod-static-nodes.service                                                                
  177ms wpa_supplicant.service                                                                   
  172ms systemd-remount-fs.service                                                               
  169ms livesys.service                                                                          
  151ms plymouth-read-write.service                                                              
  141ms netcf-transaction.service                                                                
  137ms var-lib-nfs-rpc_pipefs.mount                                                             
  125ms rpc-statd-notify.service                                                                 
  112ms systemd-fsck-root.service                                                                
   86ms user-runtime-dir@1000.service                                                            
   76ms systemd-update-utmp.service                                                              
   73ms systemd-rfkill.service                                                                   
   51ms dracut-pre-pivot.service                                                                 
   44ms sysroot.mount                                                                            
   41ms initrd-cleanup.service                                                                   
   37ms rtkit-daemon.service                                                                     
   31ms dracut-pre-udev.service                                                                  
   31ms dracut-shutdown.service                                                                  
   31ms livesys-late.service                                                                     
   27ms systemd-user-sessions.service                                                            
   21ms sys-fs-fuse-connections.mount                                                            
   19ms plymouth-start.service                                                                   
   19ms systemd-update-utmp-runlevel.service                                                     
   12ms initrd-udevadm-cleanup-db.service                                                        
    8ms iscsi-shutdown.service                                                                   
    6ms tmp.mount                                                                                
    4ms sys-kernel-config.mount                                                                  
Startup finished in 3.994s (firmware) + 1min 23.982s (loader) + 3.130s (kernel) + 18.307s (initrd) + 1min 14.211s (userspace) = 3min 3.626s 
graphical.target was never reached

That is not consistent with the first, although 3mins is still not impressive. Then I decided to reboot with the default parameters once more. The analyses for the third trial follows

Third Trial
26.933s firewalld.service                                                                        
16.848s systemd-journal-flush.service                                                            
15.690s ModemManager.service                                                                     
13.542s dracut-initqueue.service                                                                 
10.937s avahi-daemon.service                                                                     
10.716s bluetooth.service                                                                        
10.656s NetworkManager-wait-online.service                                                       
10.372s abrtd.service                                                                            
10.352s systemd-logind.service                                                                   
10.350s systemd-machined.service                                                                 
10.175s systemd-cryptsetup@luks\xA30.service      
10.011s systemd-cryptsetup@luks\x333.service      
 9.758s dbus-broker.service                                                                      
 8.855s lvm2-monitor.service                                                                     
 7.933s initrd-switch-root.service                                                               
 7.874s systemd-udev-settle.service                                                              
 7.635s smartd.service                                                                           
 5.956s systemd-cryptsetup@luks\xA07.service      
 5.182s sysstat.service                                                                          
 5.147s lm_sensors.service                                                                       
 4.128s httpd.service                                                                            
 3.837s php-fpm.service                                                                          
 3.668s libvirtd.service                                                                         
 3.330s cups.service                                                                             
 2.854s systemd-fsck@dev-disk-by\x2duuid-0266\x2dF989.service                                    
 2.425s systemd-udevd.service                                                                    
 1.711s gssproxy.service                                                                         
 1.446s systemd-backlight@backlight:intel_backlight.service                                      
 1.105s systemd-tmpfiles-setup-dev.service                                                       
  999ms NetworkManager.service                                                                   
  995ms rsyslog.service                                                                          
  912ms user@1000.service                                                                        
  871ms polkit.service                                                                           
  869ms systemd-journald.service                                                                 
  828ms systemd-fsck@dev-disk-by\x2duuid-999.service
  740ms systemd-tmpfiles-setup.service                                                           
  686ms colord.service                                                                           
  658ms chronyd.service                                                                          
  642ms systemd-fsck@dev-mapper-luks\xA07.service 
  585ms auditd.service                                                                           
  575ms systemd-vconsole-setup.service                                                           
  537ms systemd-udev-trigger.service                                                             
  501ms boot.mount                                                                               
  416ms dev-mapper-luks\x333.swap                 
  408ms dmraid-activation.service                                                                
  339ms readonly-root.service                                                                    
  323ms systemd-rfkill.service                                                                   
  299ms boot-efi.mount                                                                           
  249ms systemd-modules-load.service                                                             
  243ms systemd-random-seed.service                                                              
  237ms home.mount                                                                               
  213ms initrd-parse-etc.service                                                                 
  206ms systemd-sysctl.service                                                                   
  196ms dev-hugepages.mount                                                                      
  195ms dev-mqueue.mount                                                                         
  194ms sys-kernel-debug.mount                                                                   
  180ms plymouth-switch-root.service                                                             
  180ms kmod-static-nodes.service                                                                
  179ms sys-fs-fuse-connections.mount                                                            
  177ms nfs-convert.service                                                                      
  158ms systemd-fsck-root.service                                                                
  154ms wpa_supplicant.service                                                                   
  149ms plymouth-read-write.service                                                              
  145ms dracut-cmdline.service                                                                   
  143ms var-lib-nfs-rpc_pipefs.mount                                                             
  138ms rpc-statd-notify.service                                                                 
  112ms systemd-remount-fs.service                                                               
  109ms netcf-transaction.service                                                                
   81ms livesys.service                                                                          
   77ms systemd-update-utmp.service                                                              
   60ms systemd-user-sessions.service                                                            
   48ms dracut-pre-pivot.service                                                                 
   44ms plymouth-quit-wait.service                                                               
   42ms user-runtime-dir@1000.service                                                            
   41ms plymouth-quit.service                                                                    
   32ms rtkit-daemon.service                                                                     
   31ms dracut-pre-udev.service                                                                  
   31ms sysroot.mount                                                                            
   28ms dracut-shutdown.service                                                                  
   24ms initrd-cleanup.service                                                                   
   18ms systemd-update-utmp-runlevel.service                                                     
   17ms plymouth-start.service                                                                   
   13ms livesys-late.service                                                                     
   10ms tmp.mount                                                                                
    9ms initrd-udevadm-cleanup-db.service                                                        
    5ms iscsi-shutdown.service                                                                   
    4ms sys-kernel-config.mount                                                                  
Startup finished in 3.222s (firmware) + 16.359s (loader) + 3.075s (kernel) + 17.164s (initrd) + 1min 8.678s (userspace) = 1min 48.500s 
graphical.target was never reached

Now it all concludes within 2-mins, I am lost. :scream:
There’s got to be a way to predictably achieve plausible boot times

Something broken, probably:

Nah, that one is because I boot to level-3 (that way I login from the terminal – I use Sway and it performs better when I do not pass through gdm)

1 Like

It’s possible that the time waiting for LUKS passphrase entry is accounted for in dracut initqueue and why each attempt has different waits. I don’t think attachments are possible here, but you can put it on nextcloud, or dropbox/googledrive, and post the URL in the discussion and someone might get a moment to look at where the delay is coming from.

Yes the passphrase entry is counted.

There you go:
bug-journal.txt

I know I’m coming in late, here, but one thing jumps out at me: if you’re not using (or don’t have) a modem, you can start off by masking ModemManager.service. The same goes for lvm2 if you’re not using it, and any other services that aren’t applicable to your box.

I don’t have the best advice to give about this, but I think you’re correct to wonder why boot is so slow. The journal suggests multiple instances of decently large time gaps.

[ 69.249326] zinox.ict.esut.edu.ng rngd[898]: [pkcs11]: Initialization Failed
[ 77.293626] zinox.ict.esut.edu.ng bluetoothd[886]: Loading LTKs timed out for hci0

That’s a bit tedious to take on all at once without a bit more to go on, because systemd can do things in parallel. So at the moment, the journal with debug info is too much information. So try

$ systemd-analyze critical-chain

Another possibly useful way to look at what’s depending on what, and taking too long

$ systemd-analyze plot > plot.svg

And drop that svg file onto firefox.

Is Fedora clean installed? Or is it an upgrade?

What do you get for:

$ sudo smartctl -x /dev/sda

And also for sdb. I have no reason to suspect a drive going bad, but … it might suggest an explanation.

My bets:

A

There is a lot of messages

Found redundant job X, dropping from transaction.

[ 5.162691] – First at this time. But there is a lot of such messages, also after your log in:

[  112.617655] ... LOGIN ON tty1 BY twohot

B

[ 37.315475] – There your’ve rather big journal. This potentially can be trouble:

System Journal ... is 2.4G, max 4.0G, 1.5G free.

C

[ 6.008830] – See (original is two lines):

dev-disk-by\x2dpartlabel-Basic\x5cx20data\x5cx20partition.device:

Device dev-disk-by\x2dpartlabel-Basic\x5cx20data\x5cx20partition.device

appeared twice with different sysfs paths

/sys/devices/pci0000:00/0000:00:17.0/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda1
and
/sys/devices/pci0000:00/0000:00:17.0/ata1/host0/target0:0:0/0:0:0:0/block/sda/sda4,

ignoring the latter.

D

[ 17.876501]

systemd-hibernate-resume[577]: Could not resume from

'/dev/mapper/luks-32ceb1a2-1d78-4b1d-bbad-409ec0a074c7' (253:1).

[ 17.878907]

kernel: PM: Image not found (code -22)

[ 17.921485]

systemd-tmpfiles[578]:
Failed to determine whether '/var/log/journal' is below autofs, ignoring: No such file or directory

E

[ 18.920702] – If that mean FINAL, then skip. But if this mean “i’m reached this target and now begin to connect to the remote file systems…”…

Reached target Remote File Systems.

F

[ 3.185955] — First at this time, but there is a lot of “Failed/couldn’t” later, with

No such file or directory

G

Something failed:

[   69.247001] ... rngd[898]: [pkcs11]: No pkcs11 slots available
[   69.249326] ... rngd[898]: [pkcs11]: Initialization Failed
[   77.293626] ... bluetoothd[886]: Loading LTKs timed out for hci0

H

“Duplicates”?

[   64.116449]  systemd[973]: /run/systemd/unit-root/dev                 (rw-implicit) is duplicate.
[   64.116494]  systemd[973]: /run/systemd/unit-root/home              (rw-implicit) is duplicate.
[   64.116545]  systemd[973]: /run/systemd/unit-root/proc                   (rw-implicit) is duplicate.
[   64.116591]  systemd[973]: /run/systemd/unit-root/root                     (rw-implicit) is duplicate.
[   64.116639]  systemd[973]: /run/systemd/unit-root/run/user             (rw-implicit) is duplicate.
[   64.116691]  systemd[973]: /run/systemd/unit-root/sys                      (read-only) is duplicate.
[   64.116736]  systemd[973]: /run/systemd/unit-root/sys                      (rw-implicit) is duplicate.
[   64.116779]  systemd[973]: /run/systemd/unit-root/sys/fs/cgroup     (rw-implicit) is duplicate.

I

Miscellaneous
[    3.175262]  systemd[1]: Setting 'fs/file-max' to '9223372036854775807'.
[    3.175285]  systemd[1]: Setting 'fs/nr_open' to '2147483640'.
[    3.175294]  systemd[1]: Couldn't write fs.nr_open as 2147483640, halving it.
[    3.175305]  systemd[1]: Setting 'fs/nr_open' to '1073741816'.
[    3.175313]  systemd[1]: Successfully bumped fs.nr_open to 1073741816
[    3.175537]  systemd[1]: Found cgroup2 on /sys/fs/cgroup/, full unified hierarchy
[    3.175540]  systemd[1]: Unified cgroup hierarchy is located at /sys/fs/cgroup.
[    3.175892]  systemd[1]: Couldn't move remaining userspace processes, ignoring: Input/output error
[   23.216245]  systemd[1]: Couldn't move remaining userspace processes, ignoring: Input/output error
[    3.185652]  systemd[1]: Got EBADF when using         BPF_F_ALLOW_MULTI, which indicates it is supported. Yay!
[  111.991009]  systemd[1476]: Didn't get EBADF from BPF_PROG_DETACH, BPF firewalling is not supported: Operation not permitted
[  112.004404]  systemd[1476]: Not enough privileges, BPF device control is not supported.
[    3.185955]  systemd[1]: Failed to stat /etc/localtime, ignoring: No such file or directory
[    3.186994]  systemd[1]: /etc/localtime doesn't exist yet, watching /etc instead.
[    4.762708]  systemd[1]: Failed to read pids.max attribute of cgroup root, ignoring: No such file or directory
[   15.414491]  systemd-tty-ask-password-agent[523]: Invalid password file /run/systemd/ask-password/ask.QRQt3c
[   15.414587]  systemd-tty-ask-password-agent[523]: Failed to process password: Bad message
[    6.168104]  dracut-initqueue[536]: <debug> [1579452225.2474] platform-linux: error reading net:/sys/class/net/lo/phys_port_id: error reading 4096 bytes from file descriptor: Operation not supported
[    6.168933]  dracut-initqueue[536]: <debug> [1579452225.2485] platform-linux: error reading net:/sys/class/net/enp0s20f0u1/phys_port_id: error reading 4096 bytes from file descriptor: Operation not supported
[    6.177229]  dracut-initqueue[536]: <debug> [1579452225.2552] platform-linux: error reading net:/sys/class/net/enp1s0f1/phys_port_id: error reading 4096 bytes from file descriptor: Operation not supported
[    6.178640]  dracut-initqueue[536]: <trace> [1579452225.2561] settings: auto-default: cannot create auto-default connection for device enp1s0f1: disabled by "no-auto-default"
[    6.187048]  NetworkManager[536]: <debug> [1579452225.2552] platform-linux: error reading net:/sys/class/net/enp1s0f1/phys_port_id: error reading 4096 bytes from file descriptor: Operation not supported
[   12.924901]  NetworkManager[556]: <debug> [1579452231.9974] manager: (enp0s20f0u1): assume: cannot generate connection: device has no existing configuration
[   12.924938]  NetworkManager[556]: <debug> [1579452231.9974] manager: startup complete is waiting for device 'enp1s0f1' (carrier-wait)
[   79.939313]  rsyslogd[906]: imjournal from <zinox:systemd>: begin to drop messages due to rate-limiting
[   81.972335]  cupsd[1007]: Missing value on line 1871 of /var/cache/cups/job.cache.
[   83.221466]  colord[1014]: failed to get session [pid 1007]: No data available
[   83.245810]  colord[1014]: failed to get session [pid 1007]: No data available
[   83.316275]  colord[1014]: failed to get session [pid 1007]: No data available
[   86.466630]  audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  denied  { reload } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/system/iscsi.service" cmdline="" scontext=system_u:system_r:NetworkManager_t:s0 tcontext=system_u:object_r:iscsi_unit_file_t:s0 tclass=service permissive=0
                                                exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
[   86.466917]  systemd[1]: SELinux access check scon=system_u:system_r:NetworkManager_t:s0 tcon=system_u:object_r:iscsi_unit_file_t:s0 tclass=service perm=reload path=/usr/lib/systemd/system/iscsi.service cmdline=: -13
[   86.467089]  nm-dispatcher[1089]: Got message type=error sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=org.freedesktop.DBus.Error.AccessDenied error-message=SELinux policy denies access.
[   86.467089]  nm-dispatcher[1089]: Failed to reload iscsi.service: Access denied
[   86.467089]  nm-dispatcher[1089]: See system logs and 'systemctl status iscsi.service' for details.
[   86.467089]  nm-dispatcher[1089]: Bus n/a: changing state RUNNING → CLOSED
[   86.467510]  systemd[1]: Sent message type=error sender=org.freedesktop.systemd1 destination=n/a path=n/a interface=n/a member=n/a cookie=1 reply_cookie=1 signature=s error-name=org.freedesktop.DBus.Error.AccessDenied error-message=SELinux policy denies access.
[   86.467645]  systemd[1]: Failed to process message type=method_call sender=n/a destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=ReloadUnit cookie=1 reply_cookie=0 signature=ss error-name=n/a error-message=n/a: Access denied
[   86.467775]  systemd[1]: Bus private-bus-connection: changing state RUNNING → CLOSING
[   86.467893]  systemd[1]: Bus private-bus-connection: changing state CLOSING → CLOSED
[   86.467983]  systemd[1]: Got disconnect on private connection.

[   87.326771]  NetworkManager[984]: <info>  [1579448706.4059] manager: NetworkManager state is now CONNECTED_GLOBAL
[   91.405695]  chronyd[927]: Selected source 162.159.200.123

Also: Possible that this console is too well defended,
and kernel just can not conquest it on-the-go:

[    0.462076]  kernel: fbcon: Taking over console
1 Like