systemd needs too much time to boot system

English Install/Boot/Login
1

I have a fresh installation of openSUSE 12.2. The boot process takes way too long, there are several pauses during boot process.


# systemd-analyze 
Startup finished in 4917ms (kernel) + 123483ms (userspace) = 128401ms
# systemd-analyze blame
 56148ms network.service
 44788ms remount-rootfs.service
 10719ms systemd-modules-load.service
  8940ms systemd-vconsole-setup.service
  8310ms console-kit-daemon.service
  5789ms md.service
  5164ms plymouth-start.service
  3556ms var-lock.mount
  3531ms var-run.mount
  3299ms dev-hugepages.mount
  3267ms dev-mqueue.mount
...

systemd claims that network.service took 56 seconds, but the logger calls that I have added in /etc/init.d/network show that the script only needed about 16 seconds from start to exit. What is systemd doing for 40 seconds?

Although I have added “systemd.log_target=kmsg systemd.log_level=debug systemd.sysv_console=1” to the kernel command line, I still do not see any log messages of systemd like "network.service starting " and “network.service done”. How can I get such simple log information?

2

So, we can only say that your mileage may vary, depending on the hardware that you use. I do use a SSD for my boot driver, but all of the times are much less than yours. I might ask if we could look at your boot.log file to see what it might say on startup. I have a bash script for log file viewing you can use:

S.L.A.V.E. - SuSE Logfile Automated Viewer Engine - Version 2.60 - Blogs - openSUSE Forums

Here is my composite time: Startup finished in 3107ms (kernel) + 42772ms (userspace) = 45880ms

Thank You,

3

In yast /etc/sysconfig/ Editor, search for ‘wait’ and have a look at the times allocated

to speed boot up, on this PC,

  • WAIT_FOR_INTERFACES default is 30, changed to 10
  • DHCLIENT_WAIT_AT_BOOT default is 15, changed to 3

boot times are hardware and services enabled dependent, on this PC
Startup finished in 3240ms (kernel) + 18908ms (userspace) = 22148ms

services taking longer than 1 second :-
4245ms home.mount
2614ms systemd-vconsole-setup.service
2198ms NetworkManager.service
1964ms localnet.service
1735ms systemd-modules-load.service
1563ms SuSEfirewall2_setup.service
1064ms hddtemp.service
1028ms xinetd.service

Do you like Plymouth?

4

Are you sure that the boot.log would help? It just contains, which services were started (all have a OK) but no time information.

The main thing I want to find out are the reasons for the delay of about 40 seconds, where nothing seems to be happening: No log message on console 1, 7 or 10 are printed during that time.

The changes to the network configuration should not help (nevertheless I have changed the 30 to 10), as I do not use DHCP and according to the log output, the network init script takes (only) 16 seconds of the 56 seconds that are printed by systemd.

5

Remove “quiet” kernel parameter. It causes systemd to suppress all status messages about services progress.

6

I have/had the same problem, although the delays are smaller. About 40 seconds were shaved off when I disabled ntp.
Method: Yast -> System -> /etc/sysconfig editor -> Network -> General -> NETCONFIG_NTP_POLICY : change from auto to “”
(two double apostrophes).
For setting the system clock I now use ntpdate manually - later to be transferred to a cronjob
Not-starting Nepomuk reduces the delay after login by approx. 30 seconds.

7

hws38 wrote:
> I have/had the same problem, although the delays are smaller. About 40
> seconds were shaved off when I disabled ntp.
> Method: Yast -> System -> /etc/sysconfig editor -> Network -> General
> -> NETCONFIG_NTP_POLICY : change from auto to “”
> (two double apostrophes).
> For setting the system clock I now use ntpdate manually - later to be
> transferred to a cronjob

IMHO, that’s a bad idea; the normal NTP daemon works well. But there’s
no reason why NTP should be adding 40 secs to the boot time. That sounds
like somthing to file in bugzilla.

> Not-starting Nepomuk reduces the delay after login by approx. 30
> seconds.
>
>

8

As a guess - it tries to sync time during startup? Does setting NTPD_FORCE_SYNC_ON_STARTUP to “no” in /etc/sysconfig/ntp help?

9

This was one of the first things I did, as I do not like any splash screen that hides error messages.

It seems that a mkinitrd or one of the recent updates was needed to let systemd produce the debug messages. Additionally I completely removed plymouth. It looks like it is in some way related to the network startup that delays the boot process. Although the network init script returns an error (it did not do this before today), the interfaces are properly set up.

Summary of the code block: network.service is started at time 24 and exits at time 92.


    7.589679] systemd[1]: Installed new job network.service/start as 128
    7.589682] systemd[1]: Installed new job network-remotefs.service/start as 129
...
   24.646101] systemd[1]: About to execute: /etc/init.d/network start
   24.656432] systemd[1]: Forked /etc/init.d/network as 944
   24.656471] systemd[1]: network.service changed dead -> start
...
   27.247624] systemd[1]: systemd-logind.service changed start -> running
   27.247629] systemd[1]: Job systemd-logind.service/start finished, result=done
   38.000145] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   38.000158] systemd[1]: Running GC...
   38.002906] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   38.012318] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   49.501410] systemd[1]: Received SIGCHLD from PID 297 (systemd-readahe).
   49.501440] systemd[1]: Got SIGCHLD for process 297 (systemd-readahe)
   49.501465] systemd[1]: Child 297 died (code=exited, status=0/SUCCESS)
   49.501470] systemd[1]: Child 297 belongs to systemd-readahead-replay.service
   49.501486] systemd[1]: systemd-readahead-replay.service: main process exited, code=exited, status=0
   49.512044] systemd[1]: systemd-readahead-replay.service changed running -> exited
   49.512117] systemd[1]: Accepted connection on private bus.
   49.512238] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
   49.512288] systemd[1]: systemd-readahead-replay.service: cgroup is empty
   49.512323] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
   72.871572] systemd[1]: Got notification message for unit systemd-journald.service
   72.871581] systemd[1]: systemd-journald.service: Got message
   72.871590] systemd[1]: systemd-journald.service: got STATUS=Processing requests...
   83.397560] systemd[1]: Incoming traffic on syslog.socket
   83.397573] systemd[1]: syslog.socket changed listening -> running
   84.234789] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Activator.ActivationRequest() on /org/freedesktop/DBus
   84.234797] systemd[1]: Got D-Bus activation request for console-kit-daemon.service
   84.234995] systemd[1]: Trying to enqueue job console-kit-daemon.service/start/replace
   84.235353] systemd[1]: Installed new job console-kit-daemon.service/start as 226
   84.235358] systemd[1]: Enqueued job console-kit-daemon.service/start as 226
   84.235899] systemd[1]: About to execute: /usr/sbin/console-kit-daemon --no-daemon
   84.242137] systemd[1]: Forked /usr/sbin/console-kit-daemon as 1473
   84.242277] systemd[1]: console-kit-daemon.service changed dead -> start
   87.652978] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   87.657479] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   89.575234] systemd[1]: Got notification message for unit avahi-daemon.service
   89.575239] systemd[1]: avahi-daemon.service: Got message
   89.575244] systemd[1]: avahi-daemon.service: got STATUS=Registering host name hm.local
   89.577634] systemd[1]: Got notification message for unit avahi-daemon.service
   89.577638] systemd[1]: avahi-daemon.service: Got message
   89.577644] systemd[1]: avahi-daemon.service: got STATUS=Server startup complete. Host name is hm.local. Local service cookie is 3648052011.
   89.583164] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   89.694607] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   89.696101] systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
   89.696108] systemd[1]: console-kit-daemon.service's D-Bus name org.freedesktop.ConsoleKit now registered by :1.5
   89.696175] systemd[1]: console-kit-daemon.service changed start -> running
   89.696180] systemd[1]: Job console-kit-daemon.service/start finished, result=done
   89.970370] atl1 0000:02:00.0: irq 45 for MSI/MSI-X
   89.970481] atl1 0000:02:00.0: eth0 link is up 100 Mbps full duplex
   90.012961] systemd[1]: Accepted connection on private bus.
   90.013175] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.LoadUnit() on /org/freedesktop/systemd1
   90.013250] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/graphical_2etarget
   90.013421] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
   90.106570] systemd[1]: Received SIGCHLD from PID 1768 (ifstatus-route).
   90.106590] systemd[1]: Got SIGCHLD for process 1768 (ifstatus-route)
   90.106627] systemd[1]: Child 1768 died (code=exited, status=1/FAILURE)
   90.195744] systemd[1]: Received SIGCHLD from PID 1838 (ifstatus-route).
   90.195765] systemd[1]: Got SIGCHLD for process 1838 (ifstatus-route)
   90.195800] systemd[1]: Child 1838 died (code=exited, status=1/FAILURE)
   90.293323] Bridge firewalling registered
   90.297193] device eth0 entered promiscuous mode
   90.302596] systemd[1]: sys-devices-virtual-net-br0.device changed dead -> plugged
   90.302892] br0: port 1(eth0) entered forwarding state
   90.302899] br0: port 1(eth0) entered forwarding state
   90.328365] systemd[1]: Received SIGCHLD from PID 1971 (ifup-route).
   90.328386] systemd[1]: Got SIGCHLD for process 1971 (ifup-route)
   90.328424] systemd[1]: Child 1971 died (code=exited, status=1/FAILURE)
   90.350652] systemd[1]: Accepted connection on private bus.
   90.350782] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.LoadUnit() on /org/freedesktop/systemd1
   90.350857] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/graphical_2etarget
   90.351038] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
   92.783896] systemd[1]: Received SIGCHLD from PID 2273 (ifstatus-route).
   92.783917] systemd[1]: Got SIGCHLD for process 2273 (ifstatus-route)
   92.783952] systemd[1]: Child 2273 died (code=exited, status=1/FAILURE)
   92.837581] systemd[1]: Received SIGCHLD from PID 944 (network).
   92.837608] systemd[1]: Got SIGCHLD for process 944 (network)
   92.837674] systemd[1]: Child 944 died (code=exited, status=7/NOTRUNNING)
   92.837679] systemd[1]: Child 944 belongs to network.service
   92.837691] systemd[1]: network.service: control process exited, code=exited status=7
   92.837695] systemd[1]: network.service got final SIGCHLD for state start
   92.837709] systemd[1]: network.service changed start -> failed
   92.839105] systemd[1]: Job network.service/start finished, result=failed
   92.847304] systemd[1]: Unit network.service entered failed state.
   92.847360] systemd[1]: network.target changed dead -> active
   92.847366] systemd[1]: Job network.target/start finished, result=done
   92.847376] systemd[1]: remote-fs-pre.target changed dead -> active

I searched for a way to force systemd to do one thing after the other (not everything in parallel), but I could not find any. The options in /etc/sysconfig/boot seem to be only used for the old init system.

So my next step is to remove the br0 and enable debug in network config.

10

Why do you need a bridge (br0) at boot? Who wouldn’t have this device if someone/something hadn’t created a bridge. Did you install an hypervisor or something?

11

On 2012-10-23 23:56, herbertmeier wrote:
>
> Are you sure that the boot.log would help? It just contains, which
> services were started (all have a OK) but no time information.

That file is moot with systemd, it is not filled. You must use messages log instead.

–
Cheers / Saludos,

Carlos E. R.
(from 11.4 x86_64 “Celadon” (Minas Tirith))

12

Yast said that it must configure one for KVM.

The boot process seems to be some random game. Without changing anything, systemd now says that postfix needs 53 seconds and the network normal 7 seconds.

13

My advice: Don’t use YaST to configure KVM! Don’t create a permanent bridge! Create a bridge when you need it, before starting a kvm virtual machine, by running the script:

# nat2bridge

When you don’t need it anymore, delete it with the command:

# bridge2nat

nat2bridge and brid2nat are 2 different names of the same script, called vm-bridge, included in the package vmscripts](openSUSE Software) availalbe in my repo. See this post: http://forums.opensuse.org/english/get-technical-help-here/virtualization/478648-opensuse-12-2-kvm-broken-error-hypervisor-not-running.html#post2489394.

  • This is my own method, nothing official!

The boot process seems to be some random game.

You seem to have understood the concept of systemd. :wink:

14

Now I have found out, why postfix needs that much time. It opens /dev/log and writes “starting the Postfix mail system” to it. This takes 40! seconds.


22:35:44 execve("/usr/sbin/postlog", "/usr/sbin/postlog", "-t", "postfix/postfix-script", "-p", "info", "starting", "the", "Postfix", "mail", "system"], "MAIL_CONFIG=/etc/postfix", "data_directory=/var/lib/postfix", "sample_directory=/usr/share/doc/packages/postfix-doc/samples", "setgid_group=maildrop", "sendmail_path=/usr/sbin/sendmail", "mailq_path=/usr/bin/mailq", "manpage_directory=/usr/share/man", "readme_directory=/usr/share/doc/packages/postfix-doc/README_FILES", "newaliases_path=/usr/bin/newaliases", "PATH=/bin:/usr/bin:/sbin:/usr/sbin", "PWD=/var/spool/postfix", "queue_directory=/var/spool/postfix", "LANG=C", "mail_owner=postfix", "daemon_directory=/usr/lib/postfix", "SHLVL=1", "config_directory=/etc/postfix", "MAIL_LOGTAG=postfix", "html_directory=/usr/share/doc/packages/postfix-doc/html", "command_directory=/usr/sbin", "OLDPWD=/etc/postfix", "_=/usr/sbin/postlog"]) = 0 <0.000116>

22:35:44 socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 3 <0.000010>
22:35:44 connect(3, {sa_family=AF_FILE, sun_path="/dev/log"}, 110) = 0 <0.000009>
22:35:44 sendto(3, "<22>Oct 26 22:35:44 postfix/postfix-script[2096]: starting the Postfix mail system", 82, MSG_NOSIGNAL, NULL, 0) = 82 <39.725261>
22:36:24 exit_group(0)                  = ?
15

On 2012-10-26 23:16, herbertmeier wrote:
>
> Now I have found out, why postfix needs that much time. It opens
> /dev/log and writes “starting the Postfix mail system” to it. This takes
> 40! seconds.

It is probably waiting for syslog to start. Open a bugzilla…

–
Cheers / Saludos,

Carlos E. R.
(from 11.4 x86_64 “Celadon” (Minas Tirith))

16

As far as I know, systemd should provide /dev/log support until syslog is started.

17

DO NOT USE BTRFS!

I copied the root partition to an ext4 partition, created a new initrd and now boot from ext4:
Startup finished in 4206ms (kernel) + 20974ms (userspace) = 25181ms

18

Yeah I still do not trust btrfs. I set up this computer with ext4 with the intention to migrate later to btrfs (because of lzo compression) but then I realized that I like xfs better. So the only migration path I have is to move my data off my drive onto a larger disk, and then format to xfs. :frowning:

Happily my root partition is xfs even though my data is ext4. Using xfs my 5400rpm laptop drive boots at:

Startup finished in 4978ms (kernel) + 16581ms (userspace) = 21560ms

I wonder if folk can confirm btrfs boot problems. I do not have spare computer to do so, would a virtual machine work?

19

Yeah … and don’t expect to be able to copy all the data back to an ext4 partition of the same size! :wink:

20

There is supposed to be some way to convert ext4 to btrfs but it seemed messy to me. So I later decided against it as an option. Also the virtualbox tests I ran on btrfs netted me a lot of odd bugs and little benefit other than compression. So I will use xfs for as long as it is still developed.