Increased boot time since 20190314 due to...

English Install/Boot/Login
1

Since the 20190314 snapshot (which brought in the v5 kernel) I’m seeing a marked increase in boot time due to: “A stop job is running for udev Kernel Device Manager”, which is occurring on every boot. The boot carries on before the stop job times out, but is delaying boot by around 20-25 seconds…

This isn’t due (I assume) to this “systemd 241 (note: after upgrading from 239, the immediate reboot will be quite slow; this should be a one-off until the system was
booted with 241)” which was mentioned here https://lists.opensuse.org/opensuse-factory/2019-03/msg00186.html as that should be a one off delay.

If I boot with the previous 4.20.13-1 kernel I don’t see the delay.

2

From me no delay at the start, always from 8 to 9 seconds even with the kernel 5

Screenshot 20190316 130618 — Postimages](Screenshot 20190316 130618 — Postimages)

3

Operating System: openSUSE Tumbleweed 20190314
KDE Plasma Version: 5.15.2
KDE Frameworks Version: 5.55.0
Qt Version: 5.12.0
Kernel Version: 5.0.1-1-default
OS Type: 64-bit
Processors: 8 × Intel® Core™ i7-6700K CPU @ 4.00GHz
Memory: 31,1 GiB

No delays observed:

erlangen:~ # journalctl -b -u init.scope --output short-monotonic |grep target
    2.241301] erlangen systemd[1]: Reached target Remote File Systems (Pre).
    2.241337] erlangen systemd[1]: Reached target Remote File Systems.
    2.492710] erlangen systemd[1]: Reached target Initrd Root Device.
    2.493487] erlangen systemd[1]: Reached target Paths.
    2.519970] erlangen systemd[1]: Reached target Initrd Root File System.
    2.520844] erlangen systemd[1]: Reached target Local File Systems.
    2.520889] erlangen systemd[1]: Reached target System Initialization.
    2.520923] erlangen systemd[1]: Reached target Basic System.
    2.706631] erlangen systemd[1]: Reached target Initrd File Systems.
    2.706721] erlangen systemd[1]: Reached target Initrd Default Target.
    2.722660] erlangen systemd[1]: Stopped target Remote File Systems.
    2.722769] erlangen systemd[1]: Stopped target Initrd Default Target.
    2.723694] erlangen systemd[1]: Stopped target Timers.
    2.723914] erlangen systemd[1]: Stopped target Initrd Root Device.
    2.724662] erlangen systemd[1]: Stopped target Basic System.
    2.724797] erlangen systemd[1]: Stopped target Sockets.
    2.724913] erlangen systemd[1]: Stopped target System Initialization.
    2.725026] erlangen systemd[1]: Stopped target Local File Systems.
    2.725139] erlangen systemd[1]: Stopped target Swap.
    2.726667] erlangen systemd[1]: Stopped target Slices.
    2.728410] erlangen systemd[1]: Stopped target Remote File Systems (Pre).
    2.730893] erlangen systemd[1]: Stopped target Paths.
    2.957543] erlangen systemd[1]: Reached target Switch Root.
    3.563493] erlangen systemd[1]: Reached target Local File Systems (Pre).
    4.067844] erlangen systemd[1]: Reached target Swap.
    4.117300] erlangen systemd[1]: Reached target Local File Systems.
    5.039585] erlangen systemd[1]: Reached target System Initialization.
    5.041593] erlangen systemd[1]: Reached target Paths.
    5.041695] erlangen systemd[1]: Reached target Sockets.
    5.041746] erlangen systemd[1]: Reached target Basic System.
    5.090740] erlangen systemd[1]: Reached target Network.
    5.094182] erlangen systemd[1]: Reached target Sound Card.
    5.105981] erlangen systemd[1]: Reached target Remote File Systems.
    5.138576] erlangen systemd[1]: Reached target System Time Synchronized.
    5.139791] erlangen systemd[1]: Reached target Timers.
    7.965802] erlangen systemd[1]: Reached target Login Prompts.
   12.499816] erlangen systemd[1]: Reached target Multi-User System.
   12.499914] erlangen systemd[1]: Reached target Graphical Interface.
erlangen:~ #
4

I have not noticed such a delay.

5

Hmmm… :\

Hardware specific maybe ?

I run this machine without plymouth, so the delay is not only noticeable it’s visible …

This is an old machine - AMD dual core Athlon that I put together Dec 2008.

The “A stop job … Kernel Device Manager” is quite consistent on every boot at approx 13 seconds into the boot process, it waits for 17secs (I watched the counter this time) out of the 90sec timeout, then boot continues as normal.

I’m not even sure this is worth a bug report ??

I’ll add it to the growing list of “Just leave it” minor problems … I really should retire this machine :’(

6

No change here in booting times but I am seeing a boot message:

*couldn’t get size - with numbers either side
*
I thought it was down to the nvidia driver not yet being updated but on a fresh install the boot message is the same.

7

See this mailing list thread: [opensuse-support] Weird kernel message during boot - openSUSE Support - openSUSE Mailing Lists

8

Thanks for the link.

See this mailing list thread: https://lists.opensuse.org/opensuse-.../msg00086.html
9

I just found this thread and I must say I have a markedly increased boot time as well. My laptop had a SSD drive and the login came so quick that the plymouth screen was never visible. Now I se the plymouth screen for several seconds. I did a systemd-analyze blame

systemd-analyze blame
         24.263s fstrim.service
          7.707s mlocate.service
          2.713s display-manager.service
          2.174s plymouth-quit-wait.service
          1.278s firewalld.service
          1.129s postfix.service
          1.057s plymouth-switch-root.service
           736ms apparmor.service
           627ms systemd-logind.service
           572ms initrd-switch-root.service
           512ms lvm2-monitor.service
           431ms backup-rpmdb.service
           368ms dev-sda2.device
           367ms chronyd.service
           351ms lm_sensors.service
           348ms kbdsettings.service
           341ms rsyslog.service
           332ms avahi-daemon.service
           322ms logrotate.service
           321ms issue-generator.service
           321ms nscd.service
           164ms initrd-parse-etc.service
           128ms udisks2.service
           121ms upower.service
           113ms user@1000.service
           103ms systemd-udev-trigger.service
            98ms NetworkManager.service
            97ms systemd-vconsole-setup.service
            88ms polkit.service

Does anyone know what this fstrim.service is and why this takes so long?

10

It probably runs “fstrim”.

There’s a man page about that.

man fstrim

It is often used with SSD devices.

11

Thank you, nrickert, I did a check:

uli@linux-4skc:~> systemctl list-unit-files | grep fstrim
fstrim.service                                                   static         
fstrim.timer                                                     enabled        
uli@linux-4skc:~>  cat /usr/lib/systemd/system/fstrim.timer
[Unit]
Description=Discard unused blocks once a week
Documentation=man:fstrim

[Timer]
OnCalendar=weekly
AccuracySec=1h
Persistent=true

[Install]
WantedBy=timers.target
uli@linux-4skc:~>

So it seems that fstrim.service should run once a week - why is it running at every boot?

12

I don’t know. But maybe it is started to just check whether it is a week since it last ran. And maybe that time shown isn’t actually significant – it might just be sleeping for that time. I don’t know how to test for that.

13

I’m not very familiar with fstrim either, but if it’s the service running at every boot rather than the timer, it seems it could be that it hasn’t been given enough time to run to completion. AFAIUI, it only uses free timeslices at lowest priority. How many boots have you done since the last zypper dup, how big was it, and how long has your uptime been since then? My timer will be tripping in about 12 minutes.

14

Yes, nrickert and mrmazda, I just rebooted and there was no fstrim service this time. Nevertheless I am surprised that it was during boot time before. Before the reboot it showed up in the command journalctl -b |grep fstrim.service and now it shows up neither at this command nor with the command systemd-analyze blame. Nevertheless it would be good if the boot time would go down a bit as it was before.

15

Fstim runs by default on openSUSE. Since it runs in the background It won’t delay boot.


erlangen:~ # journalctl --since today -u fstrim.service 
-- Logs begin at Mon 2019-02-11 16:20:00 CET, end at Mon 2019-03-18 07:00:51 CET. --
Mar 18 06:33:20 erlangen systemd[1]: Starting Discard unused blocks on filesystems from /etc/fstab...
Mar 18 06:34:05 erlangen fstrim[27060]: /boot/efi: 84 MiB (88076288 bytes) trimmed on /dev/nvme0n1p4
Mar 18 06:34:05 erlangen fstrim[27060]: /home-SSD: 0 B (0 bytes) trimmed on /dev/sdb4
Mar 18 06:34:05 erlangen fstrim[27060]: /Tumbleweed-SSD: 0 B (0 bytes) trimmed on /dev/sdb3
Mar 18 06:34:05 erlangen fstrim[27060]: /home: 6.5 GiB (6937702400 bytes) trimmed on /dev/nvme0n1p3
Mar 18 06:34:05 erlangen fstrim[27060]: /: 2.8 GiB (2961739776 bytes) trimmed on /dev/nvme0n1p2
Mar 18 06:34:05 erlangen systemd[1]: fstrim.service: Succeeded.
Mar 18 06:34:05 erlangen systemd[1]: Started Discard unused blocks on filesystems from /etc/fstab.
erlangen:~ #

It’s the login prompt which matters:


erlangen:~ # journalctl -b -u init.scope --output short-monotonic |grep Started
    2.052238] erlangen systemd[1]: Started Setup Virtual Console.
    2.064887] erlangen systemd[1]: Started dracut ask for additional cmdline parameters.
    2.103963] erlangen systemd[1]: Started dracut cmdline hook.
    2.124706] erlangen systemd[1]: Started udev Kernel Device Manager.
    2.146299] erlangen systemd[1]: Started dracut pre-trigger hook.
    2.241384] erlangen systemd[1]: Started udev Coldplug all Devices.
    2.268765] erlangen systemd[1]: Started Show Plymouth Boot Screen.
    2.509791] erlangen systemd[1]: Started Forward Password Requests to Plymouth Directory Watch.
    2.531835] erlangen systemd[1]: Started File System Check on /dev/disk/by-uuid/8b190950-c141-4351-9198-7a9592b4fb34.
    2.729793] erlangen systemd[1]: Started Reload Configuration from the Real Root.
    2.754324] erlangen systemd[1]: Started Tell haveged about new root.
    2.755988] erlangen systemd[1]: Started Cleaning Up and Shutting Down Daemons.
    2.869763] erlangen systemd[1]: Started Setup Virtual Console.
    3.021944] erlangen systemd[1]: Started Plymouth switch root service.
    3.040699] erlangen systemd[1]: Started Cleanup udevd DB.
    3.041406] erlangen systemd[1]: Started Entropy Daemon based on the HAVEGE algorithm.
    3.431341] erlangen systemd[1]: Started Remount Root and Kernel File Systems.
    3.446958] erlangen systemd[1]: Started Load/Save Random Seed.
    3.552331] erlangen systemd[1]: Started Create Static Device Nodes in /dev.
    3.553161] erlangen systemd[1]: Started Apply Kernel Variables.
    3.553218] erlangen systemd[1]: Started udev Coldplug all Devices.
    3.555508] erlangen systemd[1]: Started Entropy Daemon based on the HAVEGE algorithm.
    3.555566] erlangen systemd[1]: Started udev Kernel Device Manager.
    3.555739] erlangen systemd[1]: Started Setup Virtual Console.
    3.555795] erlangen systemd[1]: Started Flush Journal to Persistent Storage.
    3.575560] erlangen systemd[1]: Started Network Service.
    3.971244] erlangen systemd[1]: Started Load/Save RF Kill Switch Status.
    4.077449] erlangen systemd[1]: Started Setup Virtual Console.
    4.103413] erlangen systemd[1]: Started Show Plymouth Boot Screen.
    4.155847] erlangen systemd[1]: Started Restore /run/initramfs on shutdown.
    4.166913] erlangen systemd[1]: Started Tell Plymouth To Write Out Runtime Data.
    4.190933] erlangen systemd[1]: Started Create Volatile Files and Directories.
    4.226837] erlangen systemd[1]: Started Security Auditing Service.
    4.241823] erlangen systemd[1]: Started Update UTMP about System Boot/Shutdown.
    5.008672] erlangen systemd[1]: Started Load AppArmor profiles.
    5.009520] erlangen systemd[1]: Started Watch for changes in CA certificates.
    5.009592] erlangen systemd[1]: Started Daily Cleanup of Temporary Directories.
    5.010761] erlangen systemd[1]: Started CUPS Scheduler.
    5.012378] erlangen systemd[1]: Started Self Monitoring and Reporting Technology (SMART) Daemon.
    5.015549] erlangen systemd[1]: Started hd-idle disk spindown service.
    5.017308] erlangen systemd[1]: Started irqbalance daemon.
    5.018688] erlangen systemd[1]: Started D-Bus System Message Bus.
    5.064234] erlangen systemd[1]: Started Generate issue file for login session.
    5.064777] erlangen systemd[1]: Started Machine Check Exception Logging Daemon.
    5.065292] erlangen systemd[1]: Started Save/Restore Sound Card State.
    5.065745] erlangen systemd[1]: Started Apply settings from /etc/sysconfig/keyboard.
    5.066091] erlangen systemd[1]: Started WPA Supplicant daemon (interface wlp3s0).
    5.066155] erlangen systemd[1]: Started Avahi mDNS/DNS-SD Stack.
    5.068529] erlangen systemd[1]: Started CUPS Scheduler.
    5.069443] erlangen systemd[1]: Started A remote-mail retrieval utility.
    5.081161] erlangen systemd[1]: Started Login and scanning of iSCSI devices.
    5.100830] erlangen systemd[1]: Started Permit User Sessions.
    5.114791] erlangen systemd[1]: Started NTP Server Daemon.
    5.115352] erlangen systemd[1]: Started Backup of RPM database.
    5.115892] erlangen systemd[1]: Started Backup of jAlbum projects.
    5.117326] erlangen systemd[1]: Started Daily rotation of log files.
    5.118348] erlangen systemd[1]: Started Daily locate database update.
    5.118440] erlangen systemd[1]: Started Backup of /etc/sysconfig.
    5.118546] erlangen systemd[1]: Started Discard unused blocks once a week.
    5.160224] erlangen systemd[1]: Started Manage, Install and Generate Color Profiles.
    5.210715] erlangen systemd[1]: Started The Apache Webserver.
    5.709153] erlangen systemd[1]: Started Login Service.
    5.811513] erlangen systemd[1]: Started Locale Service.
    5.836561] erlangen systemd[1]: Started Postfix Mail Transport Agent.
    5.837567] erlangen systemd[1]: Started Command Scheduler.
    7.948062] erlangen systemd[1]: Started Hold until boot process finishes up.
    7.949416] erlangen systemd[1]: Started Getty on tty1.
**    8.472135] erlangen systemd[1]: Started X Display Manager.**
    8.673934] erlangen systemd[1]: Started User Runtime Directory /run/user/475.
    8.808690] erlangen systemd[1]: Started User Manager for UID 475.
    8.809172] erlangen systemd[1]: Started Session 1 of user sddm.
erlangen:~ #