[SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

TioDuke · 2018-08-10 08:45:07

Hi,

I've been having this issue where every time I have to reboot my computer it takes so long beween the grub screen and the plasma desktop that it is almost unberable. After some digging, I narrowed it down to udisks2 failing to start due to a timeout.

Here are the results of 'journalctl -u udisks2':

Aug 09 18:42:37 desktop systemd[1]: Starting Disk Manager...
Aug 09 18:42:38 desktop udisksd[746]: udisks daemon version 2.7.7 starting
Aug 09 18:44:07 desktop systemd[1]: udisks2.service: Start operation timed out. Terminating.
Aug 09 18:44:27 desktop udisksd[746]: udisks daemon version 2.7.7 exiting
Aug 09 18:44:27 desktop systemd[1]: udisks2.service: Failed with result 'timeout'
Aug 09 18:44:27 desktop systemd[1]: Failed to start Disk Manager.
Aug 09 18:44:27 desktop systemd[1]: Starting Disk Manager...
Aug 09 18:44:27 desktop udisksd[1316]: udisks daemon version 2.7.7 starting
Aug 09 18:44:59 desktop systemd[1]: Started Disk Manager.
Aug 09 18:44:59 desktop udisksd[1316]: Acquired the name org.freedesktop.UDisks2 on the system message bus

As you can see, on the second try it succeds and the boot process can go on (plasma shell is somehow dependent on udisks2).

Here are the results of 'systemd-analyse critical-chain':

graphical.target @12.170s
└─multi-user.target @12.170s
  └─getty.target @12.168s
    └─getty@tty1.service @12.168s
      └─systemd-user-sessions.service @11.732s +434ms
        └─network.target @11.723s
          └─network-pre.target @11.723s
            └─iptables.service @10.081s +1.641s
              └─basic.target @10.076s
                └─sockets.target @10.076s
                  └─dbus.socket @10.076s
                    └─sysinit.target @10.043s
                      └─systemd-update-done.service @10.029s +13ms
                        └─ldconfig.service @8.975s +1.052s
                          └─local-fs.target @8.971s
                            └─srv-nfs4-documents.mount @8.967s +3ms
                              └─home.mount @8.652s +269ms
                                └─systemd-fsck@dev-sda7.service @7.832s +784ms
                                  └─dev-sda7.device @7.831s

And of 'systemd-analyze blame':

         31.276s udisks2.service
          4.721s dev-sda5.device
          4.121s org.cups.cupsd.service
          3.178s systemd-hwdb-update.service
          1.841s polkit.service
          1.641s iptables.service
          1.427s lm_sensors.service
          1.404s network@eth0.service
          1.384s systemd-sysusers.service
          1.372s systemd-journal-flush.service
          1.306s systemd-logind.service
          1.301s gssproxy.service
          1.105s nfs-server.service
          1.064s systemd-modules-load.service
          1.052s ldconfig.service
          1.026s alsa-restore.service
          1.024s rc-local.service
           845ms colord.service
           784ms systemd-fsck@dev-sda7.service
           763ms systemd-tmpfiles-setup-dev.service
           593ms proc-fs-nfsd.mount
           540ms user@1000.service
           528ms rpc-statd.service
           516ms nfs-mountd.service
           515ms nfs-idmapd.service
           441ms ntpd.service
           434ms systemd-user-sessions.service
           431ms systemd-sysctl.service
           425ms systemd-tmpfiles-setup.service
           421ms sys-kernel-config.mount
           374ms dev-hugepages.mount
           374ms dev-mqueue.mount
           372ms sys-kernel-debug.mount
           371ms systemd-journal-catalog-update.service
           358ms upower.service

It states that udisks2 took ~31s which is not perfect but it is livable (considering this is not an SDD). But I think it only takes into account the last successful try, not the one that times out.

I am pasting my fstab, just in case:

shm                            /dev/shm            tmpfs   nodev,nosuid                        0      0
/dev/sda5                      /                   ext4    defaults,noatime,errors=remount-ro  0      1
/dev/sda6                      none                swap    defaults                            0      0
/dev/sda7                      /home               xfs     defaults,relatime                   0      2
/home/sergio/Videos            /srv/nfs4/videos    none    bind                                0      0
/home/sergio/Documents         /srv/nfs4/documents none    bind                                0      0
/dev/disk/by-label/DATA_BACKUP /data               ext4    defaults,noatime,noauto             0      0

As you can see, I have two NFS "shares". The '/dev/disk/by-label/DATA' is an external HDD that is 'hidden' to the UI with this udev rule:

ENV{DEVTYPE}=="partition", ENV{ID_FS_UUID}=="07ae7378-9619-47e3-8a93-54e462d39377", ENV{UDISKS_IGNORE}="1"

This problem has been bugging me for months now, maybe for a year (I really don't reboot that much). I do not know where else to look.

Thank you in advance.

Last edited by TioDuke (2018-08-20 12:09:50)

berbae · 2018-08-10 09:12:55

How is the udisks2.service started ?
Did you enable it yourself ?
Because this is not necessary to enable it, it should be started automatically when needed.
In your case plasma should start it when launched.
Post the output of 'systemctl status udisks2.service'.

TioDuke · 2018-08-10 11:35:54

udisks2 is started by plasma, via dbus. Although, I also tried enabling the service myself, but that did not work either.

Here is the output of 'systemctl status udisks2':

 udisks2.service - Disk Manager
   Loaded: loaded (/usr/lib/systemd/system/udisks2.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2018-08-10 05:47:26 EDT; 1h 41min ago
     Docs: man:udisks(8)
 Main PID: 1072 (udisksd)
    Tasks: 5 (limit: 4915)
   Memory: 4.5M
   CGroup: /system.slice/udisks2.service
           └─1072 /usr/lib/udisks2/udisksd

Aug 10 05:46:31 desktop systemd[1]: Starting Disk Manager...
Aug 10 05:46:31 desktop udisksd[1072]: udisks daemon version 2.7.7 starting
Aug 10 05:47:26 desktop systemd[1]: Started Disk Manager.
Aug 10 05:47:26 desktop udisksd[1072]: Acquired the name org.freedesktop.UDisks2 on the system message bus

As you can see everything seems fine, as it outputs the latest attempt to launch, which was successful.

Last edited by TioDuke (2018-08-10 12:35:16)

seth · 2018-08-10 13:20:37

Please disable the service again and provide an updated and complete journal.

Wild guess:

beween the grub screen and the plasma desktop

Do you auto-start plasma via startx/xinit? Please paste your xinitrc in case.

Trilby · 2018-08-10 14:21:12

Seth's suggested diagnostic test will address what I was going to point out: you are looking at the wrong systemd-analyze output. The "blame" output should not be used the way you are using it. It does say that udisks2 is taking 31 seconds, true, but the critical-chain output makes it clear that this is not delaying any other processes. Systemd starts processes in parallel, so you can be in your desktop well before a slow background process completes.

If any other processes were waiting on udisks2 to complete, it should be in the critical-chain list. But it's not. There may be some problem with your udisks2 set up that could be worth tracking down, but from what's been presented in this thread, I doubt that is the cause of your slow start up (at least not directly).

Also a plain `systemd-analyze` output might be helpful. You are reporting 2 minutes, but "critical-chain" is showing 12 seconds. Are you sure the delay isn't in POST, or the kernel/initramfs stages?

Last edited by Trilby (2018-08-10 14:23:35)

TioDuke · 2018-08-13 10:38:45

Sorry I took so long to reply but I've been busy trying some things to solve the problem.

First of all, answering your questions:

1) The plasma session is started via sddm. As this is the family desktop PC, sddm autologins to user 'sergio' (myself). So no human intervention until plasmashell is ready.

2) There are some autostarted applications on plasmashell initialisation: klipper (clipboard manager), kmix (sound volume applet), choqok (microblog client), akregator (rss reader), keepassxc (password manager) and conky. When usdisks2 is started (and times out) automatically via dbus, some of these applications fail to properly initialize (no tray icon, runaway processes some times) and I have to kill then start them manually, this happens mainly to klipper, kmix, choqok and akregator. This is a big annoyance, maybe bigger than the slow boot time.

3) Since my latest post, I did some cleanup of my system : got rid of syslog-ng (I was planning to do it for quite some time), got rid of KDE Telepathy (I was not using it and it was behaving badly + plenty of messages in journald). I also changed back the virtual terminal in sddm: I went from vt7, which I have set up many moons ago, to the default / expected vt1. I did all this to help debug my problem.

4) I also reinstalled and enabled haveged in order to give the system some entropy, as I read some place not having enough entropy could make your boot up process more slow.

Since my latest post I played a lot enabling and disabling udisks2 service. This is what I discovered :

1) If I enable udisks2 service, the first time I boot with the service enabled, udisks2 times out and fails to start. It restarts automatically and all is good except for klipper, kmix, choqok and akregator not playing nice. I will post a journald log so that you could see the messages given by plasmashell / kded5 while they try to initialize these applications. Mainly waiting for udisks2 and dbus telling that udisks2 initialization timed out.

2) The second time I boot up with the service enabled, udisks2 still takes some time (aprox. 1m 30s) but I do not see any timeout messages nor any failure and all the autostarted applications work OK. Maybe boot time is a little bit faster, but this could be just subjective.

3) If I then disable usdisks2 service, the first time I boot up everything is fine either: no udisks2 failing, no timeouts, no failed autostarted applications.

4) The second time I boot up with the service disabled (and any subsequent reboots), I am back to having udisks2 failing, the timeouts and some failed autostarted applications (klipper, kmix, choqok and akregator).

I know this sounds weird. I find it weird too. Maybe the problem is udisks2 not terminating properly when started automatically by dbus (and the service is disabled) which causes the next starting up to fail and then to succeed when restarted by systemd immediately afterwards. While being started via systemd (service enabled) makes it to terminate properly as systemd "keeps track" of it and attempts to stop it.

Anyway, I will post now the information (logs, systemd-analyse output) with the service enabled (my current setup because is the less annoying). I will try to post the same information in a next post after I reboot (these subsequent post may take some time).

Output of 'systemd-analyze critical-chain' :

graphical.target @1min 30.427s
└─udisks2.service @12.217s +1min 18.210s
  └─basic.target @12.185s
    └─sockets.target @12.185s
      └─org.cups.cupsd.socket @12.185s
        └─sysinit.target @12.156s
          └─systemd-update-done.service @12.129s +27ms
            └─ldconfig.service @10.768s +1.359s
              └─local-fs.target @10.764s
                └─run-user-1000.mount @29.592s
                  └─swap.target @6.263s
                    └─dev-sda6.swap @5.415s +847ms
                      └─dev-sda6.device @5.414s

Output of 'systemd-analyze blame' :

    1min 18.210s udisks2.service
          7.294s org.cups.cupsd.service
          3.742s home.mount
          3.712s dev-sda5.device
          2.708s lm_sensors.service
          2.257s polkit.service
          1.930s network@eth0.service
          1.926s systemd-logind.service
          1.876s rc-local.service
          1.875s alsa-restore.service
          1.850s gssproxy.service
          1.845s iptables.service
          1.839s user@1000.service
          1.806s systemd-hwdb-update.service
          1.495s systemd-journal-flush.service
          1.359s ldconfig.service
          1.343s pkgstats.service
          1.318s systemd-sysusers.service
          1.236s systemd-modules-load.service
          1.193s colord.service
           976ms proc-fs-nfsd.mount
           847ms dev-sda6.swap
           822ms nfs-server.service
           725ms ntpd.service
           628ms systemd-fsck@dev-sda7.service
           522ms nfs-idmapd.service
           516ms systemd-tmpfiles-setup-dev.service
           489ms systemd-tmpfiles-setup.service
           454ms upower.service
           424ms systemd-journal-catalog-update.service
           400ms logrotate.service
           392ms rpc-statd.service
           372ms nfs-mountd.service
           343ms systemd-binfmt.service
           290ms systemd-udevd.service

Output of 'systemd-analize':

Startup finished in 9.863s (kernel) + 1min 30.428s (userspace) = 1min 40.292s
graphical.target reached after 1min 30.427s in userspace

Output of 'journalctl -u udisks2.service':

Aug 12 21:38:23 desktop systemd[1]: Starting Disk Manager...
Aug 12 21:38:23 desktop udisksd[458]: udisks daemon version 2.7.7 starting
Aug 12 21:39:41 desktop udisksd[458]: Acquired the name org.freedesktop.UDisks2>
Aug 12 21:39:41 desktop systemd[1]: Started Disk Manager.

And the complete log is pasted here: http://paste.ubuntu.com/p/Z7cZDMVkCp/

As I said before, I will post the same information with the service disabled and all the timeout messages in my next post.

Thank you for your help.

Last edited by TioDuke (2018-08-13 10:41:31)

seth · 2018-08-13 15:38:04

Just a hunch: disable dropbox. If this is not it, boot into the multi-user.target and start the udisks2 service "by hand". If this is slow as well, stop the service and strace /usr/lib/udisks2/udisksd to see where it's spending most time.

TioDuke · 2018-08-14 16:19:41

Thank you seth. Your hunch seems to be right. This is what happened:

1) I disabled udisks2.service and reboot. I got the usual udisks' timeouts and failing to initialize on first attempt. As usual it worked the second time. I got some autostarted applications to fail on me, as usual.

2) I disabled drobpox service (twice as I have two accounts: one for myself and another one for my wife).

3) Finally when I rebooted, I got a start up time that looked more normal. Also no timeouts, no udisks failures and all autostarted applications working normally.

This is the output of 'systemd-analyze':

Startup finished in 3.572s (kernel) + 12.645s (userspace) = 16.217s
graphical.target reached after 9.879s in userspace

This is the output of 'systemd-analyze critical-chain':

graphical.target @9.879s
└─multi-user.target @9.879s
  └─apcupsd.service @9.504s +373ms
    └─network-online.target @9.502s
      └─network.target @9.498s
        └─network@eth0.service @7.376s +2.121s
          └─basic.target @7.361s
            └─sockets.target @7.361s
              └─org.cups.cupsd.socket @7.361s
                └─sysinit.target @7.332s
                  └─systemd-update-utmp.service @7.278s +54ms
                    └─systemd-tmpfiles-setup.service @7.032s +223ms
                      └─local-fs.target @7.030s
                        └─srv-nfs4-videos.mount @7.025s +5ms
                          └─home.mount @6.502s +471ms
                            └─systemd-fsck@dev-sda7.service @5.674s +804ms
                              └─dev-sda7.device @5.673s

And finally from 'systemd-analyze blame':

         13.582s udisks2.service
          3.396s dev-sda5.device
          3.145s org.cups.cupsd.service
          2.199s nfs-idmapd.service
          2.121s network@eth0.service
          2.076s gssproxy.service
          1.737s systemd-logind.service
          1.724s lm_sensors.service
          1.721s iptables.service
          1.684s polkit.service
          1.334s systemd-journal-flush.service
          1.227s systemd-modules-load.service
          1.043s systemd-tmpfiles-setup-dev.service
           804ms systemd-fsck@dev-sda7.service
           776ms proc-fs-nfsd.mount
           754ms rpc-statd.service
           733ms nfs-mountd.service
           666ms nfs-server.service
           608ms colord.service
           577ms systemd-udevd.service
           568ms alsa-restore.service
           563ms rc-local.service
           534ms rpc-statd-notify.service
           471ms home.mount
           374ms ntpd.service
           374ms systemd-user-sessions.service
           373ms apcupsd.service
           370ms upower.service
           369ms systemd-binfmt.service
           368ms dcron.service
           352ms rpcbind.service
           352ms user@1000.service
           245ms systemd-random-seed.service
           244ms dev-hugepages.mount
           242ms sys-kernel-debug.mount
           223ms systemd-tmpfiles-setup.service
           193ms systemd-udev-trigger.service

I had to manually start both dropbox' instances, though. Do you know what can be done to start both services only after udisks finished initialization? Do I have to declare an 'After' element on dropbox service? A 'Conflicts' one?

Thank you very much.

seth · 2018-08-14 20:23:19

https://wiki.archlinux.org/index.php/Dr … ur_WM.2FDE
https://wiki.archlinux.org/index.php/Dr … th_systemd

The dropbox@.service seems to have local FS and network-online as "After" requirements already, you could add udisks2 there.

TioDuke · 2018-08-14 22:27:17

Thank you again for your suggestions. However, modifying the dropbox service to add udisks2 as an after "dependeny" did not work.

This is what I ended up doing:

1) Disabled both dropbox@user.service and enabled them for each user via systemctl --user enable dropbox

2) As it was still interfering with udisks2 service, I decided to modify the dropbox service to add a delay of 2 minutes before starting up (not very elegant). I did so by adding the following lines to the [Unit] section :

ExecStartPre=sleep 2m
TimeoutStartSec=infinity

Not very elegant, I know but it now works.

Here is the output of 'systemd-analyze':

Startup finished in 3.654s (kernel) + 13.941s (userspace) = 17.595s
graphical.target reached after 10.192s in userspace

Here is the output of 'systemd-analyze critical-chain':

graphical.target @10.192s
└─multi-user.target @10.192s
  └─ntpd.service @9.935s +256ms
    └─network.target @9.929s
      └─network@eth0.service @7.776s +2.152s
        └─basic.target @7.711s
          └─sockets.target @7.711s
            └─dbus.socket @7.710s
              └─sysinit.target @7.685s
                └─systemd-update-utmp.service @7.615s +69ms
                  └─systemd-tmpfiles-setup.service @7.380s +225ms
                    └─local-fs.target @7.379s
                      └─srv-nfs4-videos.mount @7.375s +4ms
                        └─home.mount @6.969s +362ms
                          └─systemd-fsck@dev-sda7.service @6.336s +605ms
                            └─dev-sda7.device @6.335s

Last edited by TioDuke (2018-08-14 22:27:54)

TioDuke · 2018-08-20 12:07:43

Finally I took the plunge and replaced Dropbox with Syncthing, which is perfect for my use case. It works fine and it doesn't require any hacks in systemd units files. I am marking this thread as SOLVED.

Thanks to everyone involved.

Arch Linux

#1 2018-08-10 08:45:07

[SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#2 2018-08-10 09:12:55

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#3 2018-08-10 11:35:54

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#4 2018-08-10 13:20:37

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#5 2018-08-10 14:21:12

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#6 2018-08-13 10:38:45

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#7 2018-08-13 15:38:04

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#8 2018-08-14 16:19:41

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#9 2018-08-14 20:23:19

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#10 2018-08-14 22:27:17

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

#11 2018-08-20 12:07:43

Re: [SOLVED] udisks2 taking more than 2 minutes to start makes boot tim...

Board footer