Long boot time > 1min udisk2.service

Hi all,

after upgrading to opensuse 13.1 from 12.3 my startup time increased significantly.

typing
systemd-analyze blame
in a shell:

1min 17.664s udisks2.service
21.483s network.service
20.224s network@enp0s10.service
1.556s plymouth-start.service
…]

The booting up to the login is not too fast, but that might be another issue. Anyhow, starting KDE afterwards takes ages (say 1+ minutes), including a pronounced blackscreen.

Afterwards the system is stable. Unfortunately, I could not find any help researching online the past 2 days, so I would appreciate a hint on what to check.

Greetings, Oliver

Many people noticed the slower startup with 13.1. This has improved with some of the updates. So make sure that your system is fully up to date.

Thanks for the fast answer, unfortunately, after updating, the problem persists:
systemd-analyze blame
states

1min 21.790s udisks2.service
     21.549s network.service
     20.252s network@enp0s10.service
      1.746s cycle.service

…]

(only change: the blackscreen was not pronounced anymore the last time).

Any suggestions what to check as next step?
Greetings, Oliver

I’m not sure why those times are so long. But then I don’t know anything about your hardware.

After a little over 1 day of uptime, here are the top “blame” entries that I am seeing:


          6.829s SuSEfirewall2_init.service
          2.174s ModemManager.service
          2.110s wpa_supplicant.service
          2.012s avahi-daemon.service
          2.006s systemd-logind.service
          1.449s cycle.service
          1.446s systemd-udev-root-symlink.service
          1.153s kmod-static-nodes.service
          1.091s rsyslog.service

Anything else is less than 1 second. My udisks2.service is shown as 111ms.

It takes a bit longer here:

# systemd-analyze blame
...
810ms udisks2.service
...

But still far from 1 minute… :wink:

Does “sudo systemctl -l status udisks2” show any errors maybe?

You could try to kill udisksd and then run /usr/lib/udisks2/udisksd in a terminal (as root). Maybe there’s interesting output then? (the service runs it with the “–no-debug” option)

Trying #1: sudo systemctl -l status udisks2
gives me the following, without hints (from my minor knowledge):

udisks2.service - Disk Manager
Loaded: loaded (/usr/lib/systemd/system/udisks2.service; static)
Active: active (running) since So 2014-07-06 19:58:13 CEST; 2h 24min ago
Docs: man:udisks(8)
Main PID: 1317 (udisksd)
CGroup: /system.slice/udisks2.service
└─1317 /usr/lib/udisks2/udisksd --no-debug

Jul 06 19:58:13 linux-6b3y systemd[1]: Starting Disk Manager…
Jul 06 19:58:13 linux-6b3y udisksd[1317]: udisks daemon version 2.1.1 starting
Jul 06 19:58:13 linux-6b3y systemd[1]: Started Disk Manager.
Jul 06 19:58:13 linux-6b3y udisksd[1317]: Acquired the name org.freedesktop.UDisks2 on the system message bus

With #2: “killing etc” - I am not sure how to do this properly :frowning:

sudo killall udisksd

Then run:

sudo /usr/lib/udisks2/udisksd

Does this also take over a minute?
Maybe there’s some interesting output there.
It should be finished with startup when something like “Housekeeping complete” appears.

I’m not completely sure on what udisk2 does. But could this be an indication of a failing disk – perhaps a failure of the logic circuitry rather than a surface problem?

On 2014-07-06 16:36, nrickert wrote:
> After a little over 1 day of uptime, here are the top “blame” entries
> that I am seeing:

It more informative to run “systemd-analyze critical-chain”.


Cheers / Saludos,

Carlos E. R.
(from 13.1 x86_64 “Bottle” at Telcontar)

I’m not completely sure either, but it seems to look for which drives/partition are present, and get some more information about them.
F.e. it seems to read the SMART data for hard disks.

But could this be an indication of a failing disk

I would suspect something like that as well.

Thanks for all the help. Let me get through the suggestions:
First, this time the booting took as long (especially the KDE start) but the “blaming” did not show “1 minute +” - that is somewhow, strange
0: “blame”

oliver@linux-6b3y:~> systemd-analyze blame
         21.899s network.service
         20.398s network@enp0s10.service
         10.360s SuSEfirewall2_init.service
          2.229s systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD2500JS\x2d55NCB1_WD\x2dWMANK3792746\x2dpart6.service
          1.356s systemd-udev-root-symlink.service
          1.296s apparmor.service
          1.261s ModemManager.service
          1.188s cycle.service
           986ms systemd-update-utmp.service
           957ms plymouth-start.service
           904ms kmod-static-nodes.service
           821ms smpppd.service
           818ms home.mount
           673ms systemd-vconsole-setup.service
           616ms dev-mqueue.mount
           613ms sys-kernel-debug.mount
           610ms dev-hugepages.mount
           602ms systemd-tmpfiles-setup.service
           586ms SuSEfirewall2.service
           574ms systemd-readahead-collect.service
           567ms postfix.service
           561ms systemd-readahead-replay.service
           557ms systemd-remount-fs.service
           509ms dev-disk-by\x2did-ata\x2dWDC_WD2500JS\x2d55NCB1_WD\x2dWMANK3792746\x2dpart2.swap
           477ms rtkit-daemon.service
           451ms systemd-modules-load.service
           418ms polkit.service
           380ms systemd-tmpfiles-setup-dev.service
           240ms user@1000.service
           218ms xdm.service
           208ms udisks2.service
           137ms plymouth-read-write.service
           125ms systemd-sysctl.service
           100ms ntp.service
            98ms wpa_supplicant.service
            97ms systemd-udev-trigger.service
            90ms rsyslog.service
            83ms avahi-daemon.service
            74ms alsa-restore.service
            47ms systemd-logind.service
            41ms teamviewerd.service
            27ms systemd-random-seed.service
            21ms upower.service
            20ms systemd-journal-flush.service
            19ms systemd-user-sessions.service
            16ms rc-local.service
            15ms bluetooth.service
            12ms sys-fs-fuse-connections.mount
            10ms var-lock.mount
            10ms var-run.mount
             7ms systemd-hostnamed.service
             5ms systemd-readahead-done.service
             4ms systemd-udevd.service
             4ms systemd-update-utmp-runlevel.service
oliver@linux-6b3y:~> 

1: killing / starting (I started with “&” as I wanted to continue working afterwards - hoping this does not disturb anything



oliver@linux-6b3y:~> sudo /usr/lib/udisks2/udisksd &
[1] 3851
oliver@linux-6b3y:~> 17:31:55.677:[3854]:[NOTICE]: udisks daemon version 2.1.1 starting [main.c:146, main()]
17:31:55.681:[3854]:[DEBUG]: Entering main event loop [main.c:171, main()]
17:31:55.698:[3854]:[INFO]: Initialization (device probing) [udiskslinuxprovider.c:445, udisks_linux_provider_start()]
17:31:55.716:[3854]:[INFO]: Initialization (coldplug 1/2) [udiskslinuxprovider.c:457, udisks_linux_provider_start()]
17:31:55.716:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]                                                                                                                                                            
17:31:55.723:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda1 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.725:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda2 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.727:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda3 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.728:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda4 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.731:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda5 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.733:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda6 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.734:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda7 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.736:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:0/block/sdb [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.758:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:1/block/sdc [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.781:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:2/block/sdd [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.791:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:3/block/sde [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.803:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:06.0/ata5/host4/target4:0:1/4:0:1:0/block/sr0 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.804:[3854]:[INFO]: Initialization (coldplug 2/2) [udiskslinuxprovider.c:457, udisks_linux_provider_start()]
17:31:55.804:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.805:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda1 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.806:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda2 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.807:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda3 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.808:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda4 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.809:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda5 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.809:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda6 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.810:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:08.0/ata3/host2/target2:0:0/2:0:0:0/block/sda/sda7 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.810:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:0/block/sdb [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.831:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:1/block/sdc [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.854:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:2/block/sdd [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.864:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:02.0/usb2/2-7/2-7:1.0/host6/target6:0:0/6:0:0:3/block/sde [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.875:[3854]:[DEBUG]: uevent add /sys/devices/pci0000:00/0000:00:06.0/ata5/host4/target4:0:1/4:0:1:0/block/sr0 [udiskslinuxprovider.c:902, udisks_linux_provider_handle_uevent()]
17:31:55.876:[3854]:[INFO]: Initialization complete [udiskslinuxprovider.c:466, udisks_linux_provider_start()]
17:31:55.876:[3856]:[INFO]: Housekeeping initiated (0 seconds since last housekeeping) [udiskslinuxprovider.c:969, housekeeping_thread_func()]
17:31:55.877:[3856]:[INFO]: Housekeeping complete [udiskslinuxprovider.c:973, housekeeping_thread_func()]
17:31:55.877:[3854]:[DEBUG]: Connected to the system bus [main.c:53, on_bus_acquired()]
17:31:55.881:[3854]:[NOTICE]: Acquired the name org.freedesktop.UDisks2 on the system message bus [main.c:77, on_name_acquired()]
17:31:55.881:[3859]:[INFO]: Entering cleanup thread [udisksstate.c:306, udisks_state_thread_func()]
17:31:55.881:[3859]:[INFO]: Cleanup check start [udisksstate.c:419, udisks_state_check_in_thread()]
17:31:55.882:[3859]:[INFO]: Cleanup check end [udisksstate.c:457, udisks_state_check_in_thread()]

oliver@linux-6b3y:~> 

oliver@linux-6b3y:~> 17:41:56.704:[3914]:[INFO]: Housekeeping initiated (601 seconds since last housekeeping) [udiskslinuxprovider.c:969, housekeeping_thread_func()]
17:41:56.704:[3914]:[INFO]: Housekeeping complete [udiskslinuxprovider.c:973, housekeeping_thread_func()]

oliver@linux-6b3y:~> 

and again


oliver@linux-6b3y:~> 17:51:56.623:[3989]:[INFO]: Housekeeping initiated (600 seconds since last housekeeping) [udiskslinuxprovider.c:969, housekeeping_thread_func()]
17:51:56.623:[3989]:[INFO]: Housekeeping complete [udiskslinuxprovider.c:973, housekeeping_thread_func()]

oliver@linux-6b3y:~> 

Seems strange to me, anyhow, it is different from the “1 minute +” thing I had. Any suggestions?

3: retrying the sysctrl afterwards - this was surprising:


oliver@linux-6b3y:~>  sudo systemctl -l status udisks2
root's password:
udisks2.service - Disk Manager
   Loaded: loaded (/usr/lib/systemd/system/udisks2.service; static)
   Active: inactive (dead)
     Docs: man:udisks(8)

Jul 08 07:40:22 linux-6b3y systemd[1]: Starting Disk Manager...
Jul 08 07:40:22 linux-6b3y udisksd[2693]: udisks daemon version 2.1.1 starting
Jul 08 07:41:52 linux-6b3y systemd[1]: udisks2.service operation timed out. Terminating.
Jul 08 07:42:46 linux-6b3y systemd[1]: Failed to start Disk Manager.
Jul 08 07:42:46 linux-6b3y systemd[1]: Unit udisks2.service entered failed state.
Jul 08 07:42:57 linux-6b3y systemd[1]: Starting Disk Manager...
Jul 08 07:42:57 linux-6b3y udisksd[2872]: udisks daemon version 2.1.1 starting
Jul 08 07:42:58 linux-6b3y systemd[1]: Started Disk Manager.
Jul 08 07:42:58 linux-6b3y udisksd[2872]: Acquired the name org.freedesktop.UDisks2 on the system message bus
oliver@linux-6b3y:~> 

This has the right time frame. Anybody with further suggestions?

4: carlos’ suggestion: systemd-analyze critical-chain


oliver@linux-6b3y:~> systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @44.174s
└─multi-user.target @44.174s
  └─cron.service @44.173s
    └─postfix.service @43.603s +567ms
      └─time-sync.target @43.598s
        └─ntp.service @43.497s +100ms
          └─nss-lookup.target @43.492s
            └─network.target @43.484s
              └─network.service @21.584s +21.899s
                └─SuSEfirewall2_init.service @11.219s +10.360s
                  └─basic.target @11.146s
                    └─timers.target @11.144s
                      └─systemd-tmpfiles-clean.timer @11.144s
                        └─sysinit.target @11.123s
                          └─apparmor.service @9.826s +1.296s
                            └─systemd-tmpfiles-setup.service @9.223s +602ms
                              └─local-fs.target @9.203s
                                └─home.mount @8.383s +818ms
                                  └─systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD2500JS\x2d55NCB1_WD\x2dWMANK3792746\x2dpart6.service @6.124s +2.229s
                                    └─dev-disk-by\x2did-ata\x2dWDC_WD2500JS\x2d55NCB1_WD\x2dWMANK3792746\x2dpart6.device @6.123s
oliver@linux-6b3y:~> 


So, are there other hints against / for a failing disk assumption? Or further possibilities for an analysis?

Thanks a lot for the help! Greetings, Oliver

Hello all,

the issue is still unsolved.

I am not quite sure about the failing disk suggestion as the 12.3 - co installation starts without problem, nor does the disk make “strange” noises starting 13.1.

The pronounced waiting time is while starting KDE, not the system itself. Any ideas what to check next?

Thanks, Oliver

KDE startup actually is slow. So maybe you don’t have a problem.

On an older, slower, system, I login to KDE, then find something else to do for a few minutes.

On my current desktop, it looks as if it is less than a minute. But that’s just appearance. If I carefully watch the task bar, some of the icons take longer than that to show up. If the first thing that I do after startup happens to require kde-wallet, then there is a very noticeable delay before the prompt for the kwallet password shows up.

I just checked my disc using

oliver@linux-6b3y:~> sudo /usr/sbin/badblocks -vsn /dev/sda1
Suche nach defekten Blöcken im zerstörungsfreien Lesen+Schreiben-Modus
Von Block 0 bis 90590502
Suche nach defekten Blöcken (zerstörungsfreier Lesen+Schreiben-Modus)
Teste mit zufälligen Mustern: erledigt                                             
Durchgang beendet, 0 defekte Blöcke gefunden. (0/0/0 Fehler)

and I repeated it for all partitions sda1 - sda7. (ok: I had to skip one small partition because it is the swap-partition on both systems). Anyhow, no badblocks so far gives me confidence claiming that it is not the disk (please tell me if i did something wrong in testing)!

So, I got kind of stuck in analyzing, so I return to the main problem. Boot time: Perhaps this explanation of my “phenomenon” may trigger some explanations:

here the manually measured times while booting
0min 00sec: starting / Bios is seen
0min 11sec: bootloader asks which system shall be booted
0min 13sec: the black/green start pic appears (art deco - gecko on plant)
1min 16sec: login appears
1min 28sec: login finished (I had to write the status down be hand, so I needed some sec :slight_smile:
1min 33sec: KDE starting shows “disc”
1min 36sec: KDE starting shows “tools”
1min 40sec: KDE starting shows “globe”
2min 28sec: KDE starting shows “plasma” (or whatever this icon tells me)
2min 29sec: KDE starting shows “KDE”
2min 41sec: Desktop shown (does not react yet, may be blue instead of black art deco-background)
2min 53sec: Desktop reacts (plays no jingle though :frowning: ?)

Is this a normal boot sequence/time - even for older computers?

(additional fun fact (?): I just realized that I have neither a jingle after booting nor a test sound in YAST is played - anyhow, amarock etc. plays wonderfully. To get the external sound working, I have to change the sound-card “device” via alsamixer from “PulseAudio” to “NVidia CK804”. So, there seems to be some more awkward things lurking around. Anyhow, the boot time is the first task).

Greetings,
Oliver

Yes normal. maybe a bit slow but then I never put a stop watch to mine. I only reboot when a kernel is updated or power problems

But it is the normal sequence and it is taking a bit of time to get to login. And the KDE start up is slow also

Start sound is not set on the default Install You need to set the sounds yourself

Configure Desktop - Application and System Notification - KDE workspace - login.

Note you may need to setup the sound driver also depending

I just did some timing.

From grub menu to prompt for encryption key: 8 seconds.

From giving encryption key to login screen: an additional 48 seconds.

So, yes, yours seems a bit slow.

This was with a Toshiba Satellite A65 purchased in 2004, so a slow processor by today’s standards. Also, it has an IDE disk, which is slower than SATA disks. It has around 1.2G of memory. With less memory, it would be slower.

On 2014-07-21 18:26 (GMT) oli-lange composed:

> here the manually measured times while booting
> 0min 00sec: starting / Bios is seen
> 0min 11sec: bootloader asks which system shall be booted
> 0min 13sec: the black/green start pic appears (art deco - gecko on
> plant)
> 1min 16sec: login appears
> 1min 28sec: login finished (I had to write the status down be hand, so I
> needed some sec :slight_smile:
> 1min 33sec: KDE starting shows “disc”
> 1min 36sec: KDE starting shows “tools”
> 1min 40sec: KDE starting shows “globe”
> 2min 28sec: KDE starting shows “plasma” (or whatever this icon tells me)
> 2min 29sec: KDE starting shows “KDE”
> 2min 41sec: Desktop shown (does not react yet, may be blue instead of
> black art deco-background)
> 2min 53sec: Desktop reacts (plays no jingle though :frowning: ?)

> Is this a normal boot sequence/time - even for older computers?

2.6GHz P4 HT (single actual core) CPU
2G RAM
Fixed IP/no DHCP/no wireless
Single PATA HD/no other attached storage
No remote automounts
Radeon 7500 gfxchip
Option “Composite” “Disable” set in xorg.conf*
12.2
~60 seconds to unthemed KDM4 greeter ready
~95 seconds to KDE4 session restored (only Konsole)
12.3
~56 seconds to unthemed KDM4 greeter ready
~88 seconds to KDE4 session restored (only Konsole)
13.1
~61 seconds to unthemed KDM3 greeter ready
~76 seconds to KDE3 session restored (only Konsole)

Team OS/2 ** Reg. Linux User #211409 ** a11y rocks!

Felix Miata *** http://fm.no-ip.com/

it seems that the problem is still here in 13.2 KDE. i have notice myself few times, not always, the system takes long time so start and dump me to a blank screen with a mouse cursor. in this morning, this is happened again, i have entered in tty and open “journalctl -f” and the system was telling me that is trying to activate udisk2.service or something. finally, i have rebooted and the system had started normally.
still i suspect my HDD of being quite old, my laptop is manufactured in 2008 and the HDD has over 2 years of uptime.