Re: much longer boot time with jessie
Quoting Sven Hartge (sven@svenhartge.de):
> David Wright <deblis@lionunicorn.co.uk> wrote:
>
> > $ systemd-analyze blame
> > 36.727s wicd.service
> > 22.102s binfmt-support.service
> > 20.789s alsa-restore.service
> > 20.618s lm-sensors.service
> > 20.565s systemd-logind.service
> > 20.471s rsyslog.service
> > 20.468s rc-local.service
> > 20.465s systemd-user-sessions.service
> > 20.462s apmd.service
> > 20.461s virtualbox.service
> > 20.461s loadcpufreq.service
> > 20.460s gpm.service
> > 20.135s bluetooth.service
> > 19.730s exim4.service
> > 11.922s timidity.service
>
> This is very very strange. But I notice a common pattern among those
> service. Nearly all take about 20.4 seconds to start.
My guess is that bluetooth is the first service in that group (though
it wasn't when acpid was still present). Bluetooth is also the first
emitter of a boot message after a long pause just after d-bus starts.
So it may be that a number of processes are waiting on d-bus.
After removing acpid etc, these services disappeared:
acpi-support.service
console-kit-daemon.service
console-kit-log-system-start.service
rtkit-daemon.service
systemd-rfkill@rfkill4.service
systemd-rfkill@rfkill5.service
systemd-suspend.service
systemd-tmpfiles-clean.service
and the timings of various services changed markedly:
ModemManager 88s -> 43/47s, ntp 47 -> 8/6s, user@1000 8 -> 1s
were the big winners, but that clump at 20s used to be around 15s.
wicd slowed by a larger amount.
Removing modemmanager removed:
ModemManager.service
polkitd.service
but the relative timings remained very similar.
> To compare, here is a list of the top services from my workstation:
>
> 8.540s systemd-journal-flush.service
> 4.379s dev-md0.device
> 4.359s dev-dm\x2d0.device
> 4.063s accounts-daemon.service
> 3.329s munin-node.service
> 3.041s systemd-udev-settle.service
> 2.806s teamviewerd.service
> 2.743s binfmt-support.service
> 2.391s mdadm-raid.service
> 2.084s systemd-logind.service
> 2.010s loadcpufreq.service
> 1.987s irqbalance.service
> 1.973s rsyslog.service
> 1.953s systemd-user-sessions.service
> 1.942s timidity.service
> 1.940s lm-sensors.service
> 1.648s schroot.service
> 1.639s lightdm.service
> 1.598s avahi-daemon.service
> 1.408s mcelog.service
> 1.354s sensord.service
> 1.330s systemd-cryptsetup@cswap.service
> 1.224s dirmngr.service
> 1.168s autofs.service
> 1.109s virtualbox.service
>
> (systemd-journal-flush takes so long, because is set to persistent and
> has to flush the journal to a read HDD instead of to /run, which is a
> tmpfs.)
>
> As you can see, most services start in under 3 seconds. The whole
> startup from kernel to lightdm takes 29.5 seconds:
>
> Startup finished in 5.721s (kernel) + 23.808s (userspace) = 29.529s
Startup finished in 5.630s (kernel) + 1min 21.711s (userspace) = 1min 27.341s
I'm guessing that waiting for the disk gets charged to userspace
rather than the kernel?
> > I've tried to analyse the Login-BashPrompt time of 30-34 secs.
> > I added set -v to the start of .bash_profile and the end of .bashrc,
> > and set +v to the start of .bashrc and the end of .bash_profile,
> > ie excluding tracing .bashrc because it lists every function
> > as they are defined.
>
> > What I discovered is that .bash_profile is reached 16 seconds after
> > "You have new mail." and that a function which copies a lot of my
> > startup files to /tmp/.my-startups/ takes over 15 seconds to run.
> > (The disk activity light is lit through the entire boot/login process
> > and beyond.)
>
> What is that "my startup files"? This must be something special and home
> brewn on your system, right? I guess this special function runs for
> every init-script and causing the delay of your boot. Could you please
> disable whatever does this "copying of my startup files" and try again?
The startup files belong to user 1000 (me) and so are not involved with
getting to the Login prompt. The copying process only runs from my
.bash_profile and only if the target directory does not exist, ie only
once per boot. It's significance here is that the copying has to
compete with the frenetic disk activity going on at the time.
I should point out that when I type my username to the first Login
prompt, the Password prompt takes between 3 and 8 seconds to
appear. In wheezy, the delay is a fraction of a second. (Sometimes
wheezy misses the first character of my password at the rate I type,
something that never happens on all my desktop machines.)
When wheezy boots, the disk activity light goes out when the Login
prompt appears. It then flickers a few times (for anything up to a
second each time) over a period of, say, 20 seconds.
When jessie boots, the disk activity light is on hard for another
50 seconds after the Login prompt appears. (In both cases, not
trying to login.)
I think it's time for a reinstall to see what improves.
Cheers,
David.
Reply to: