You are not logged in.

#1 2013-11-30 19:57:19

slavik262
Member
From: WA, USA
Registered: 2012-07-12
Posts: 46
Website

Unexplained boot delay due to I/O flood

Update: A better synopsis of the problem can be found lower in the thread, here

When I finished the basic Arch setup and rebooted my new laptop, booting only took a few seconds. Now, after installing all the applications I normally use, it takes over 30. Unfortunately, I installed everything at once, and uninstalling things one at a time to find the source of delay would require a stupid amount of time time and effort.

sysemd-analyze plot gives this plot. Note the massive delay right before timers.target, which according to the light on my laptop, is accompanied by heavy disk I/O. Does anyone have any idea what disk-heavy process could cause the slowdown, or what I could do in order to narrow it down?

FWIW, my disk setup is Bcache, using a 16 GB SSD as the cache device and a partition on my spinning drive as the backing device. What perplexes me most is that I have all of the same applications installed on my desktop (and probably more), and despite it only containing spinning drives (at the same speed as my laptop, 7200 RPM), it boots faster.

Edit: It seems that timers.target is taking over 15 seconds. Is there any way to discover what services or processes are tied to that target?

Last edited by slavik262 (2014-04-08 18:05:23)

Offline

#2 2013-11-30 20:18:11

WonderWoofy
Member
From: Los Gatos, CA
Registered: 2012-05-19
Posts: 8,414

Re: Unexplained boot delay due to I/O flood

Sooooo... you're asking others to debug an issue you are having with your machine?  I don't think anyone else can really do that for you.  You need to dig through things and see if you can find any real evidence as to where things are getting stuck.  I think the first place you should have looked is your logs.  Without more information, no one can really help you here.

Offline

#3 2013-11-30 21:19:27

slavik262
Member
From: WA, USA
Registered: 2012-07-12
Posts: 46
Website

Re: Unexplained boot delay due to I/O flood

WonderWoofy wrote:

Sooooo... you're asking others to debug an issue you are having with your machine?

No, I'm asking if someone else (who perhaps has more familiarity with systemd) if there are any additional tools I can use to help diagnose the problem.

After having read the relevant wiki articles, looking at diagnostics (e.g. systemd-analyze info), and still getting nowhere, I posted in the basic help forum, asking if anyone had suggestions for more things I could look at. That's certainly within etiquette.

Last edited by slavik262 (2013-11-30 21:20:51)

Offline

#4 2013-11-30 21:31:54

WonderWoofy
Member
From: Los Gatos, CA
Registered: 2012-05-19
Posts: 8,414

Re: Unexplained boot delay due to I/O flood

WonderWoofy wrote:

I think the first place you should have looked is your logs.

Offline

#5 2013-11-30 21:40:08

slavik262
Member
From: WA, USA
Registered: 2012-07-12
Posts: 46
Website

Re: Unexplained boot delay due to I/O flood

Alright. Sorry if I appeared indignant. Looking at the logs (which I got with sudo journalctl -b), there is a 13 second gap between "Starting Daily Cleanup of Temporary Directories." and "Started Daily Cleanup of Temporary Directories." The relevant portion of the log is shown below.

Nov 30 13:19:50 mrkline-arch systemd[1]: Started Recreate Volatile Files and Directories.
Nov 30 13:19:50 mrkline-arch systemd[1]: Starting Update UTMP about System Reboot/Shutdown...
Nov 30 13:19:50 mrkline-arch systemd[1]: Started Update UTMP about System Reboot/Shutdown.
Nov 30 13:19:50 mrkline-arch systemd[1]: Starting System Initialization.
Nov 30 13:19:50 mrkline-arch systemd[1]: Reached target System Initialization.
Nov 30 13:19:50 mrkline-arch systemd[1]: Starting D-Bus System Message Bus Socket.
Nov 30 13:19:50 mrkline-arch systemd[1]: Listening on D-Bus System Message Bus Socket.
Nov 30 13:19:50 mrkline-arch systemd[1]: Starting Sockets.
Nov 30 13:19:50 mrkline-arch systemd[1]: Reached target Sockets.
Nov 30 13:19:50 mrkline-arch systemd[1]: Starting Daily Cleanup of Temporary Directories.
Nov 30 13:20:03 mrkline-arch systemd[1]: Started Daily Cleanup of Temporary Directories.
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Timers.
Nov 30 13:20:03 mrkline-arch systemd[1]: Reached target Timers.
Nov 30 13:20:03 mrkline-arch systemd[1]: Started Manage Sound Card State (restore and store).
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Restore Sound Card State...
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Basic System.
Nov 30 13:20:03 mrkline-arch systemd[1]: Reached target Basic System.
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Network Manager...
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Login Service...
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting D-Bus System Message Bus...
Nov 30 13:20:03 mrkline-arch systemd[1]: Started D-Bus System Message Bus.
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Permit User Sessions...
Nov 30 13:20:03 mrkline-arch systemd[1]: Started Restore Sound Card State.
Nov 30 13:20:03 mrkline-arch systemd[1]: Started Permit User Sessions.
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Getty on tty1...
Nov 30 13:20:03 mrkline-arch systemd[1]: Started Getty on tty1.
Nov 30 13:20:03 mrkline-arch systemd[1]: Starting Login Prompts.
Nov 30 13:20:03 mrkline-arch systemd[1]: Reached target Login Prompts.
Nov 30 13:20:03 mrkline-arch systemd-logind[285]: New seat seat0.
Nov 30 13:20:03 mrkline-arch systemd[1]: Started Login Service.

I'm even more confused, since my /tmp directory is mounted to a ramfs. Below is my fstab:

# UUID=9e6b90cb-acbc-4b4d-8c8d-f79ebd0b3ec3
/dev/bcache0 / ext4 defaults 0 1

# /dev/sda1
UUID=E9B8-13EB /boot vfat rw,relatime,fmask=0022,dmask=0022,codepage=437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro 0 0

UUID=6f993848-6157-4157-9a08-341298f51637 swap swap defaults 0 0

# ramfs
ramfs /tmp ramfs rw,relatime 0 0

Offline

#6 2013-11-30 21:46:10

WonderWoofy
Member
From: Los Gatos, CA
Registered: 2012-05-19
Posts: 8,414

Re: Unexplained boot delay due to I/O flood

You don't need the /tmp entry in the fstab, and in fact what you have there is less ideal than what systemd will default to.  Check out /usr/lib/systemd/system/tmp.mount and you'll see what it does for you automagically.

As far as the tmpfiles, you should see the tmpfiles.d man page.  It runs configurations that can be found in /etc/tmpfiles.d, /usr/lib/tmpfiles.d, and /run/tmpfiles.d.  Since packages ship things in /usr/lib, I would start there and see if there is anything there that might be fucking up to process.  Though I don't know why it would be delaying between the starting and started part...

Offline

#7 2013-11-30 22:52:29

slavik262
Member
From: WA, USA
Registered: 2012-07-12
Posts: 46
Website

Re: Unexplained boot delay due to I/O flood

Thanks! I didn't know about systemd's /tmp defaults. At any rate, I just rebooted and now the delay is before the Temporary Directories messages:

Nov 30 15:57:41 mrkline-arch systemd[1]: Starting Sockets.
Nov 30 15:57:41 mrkline-arch systemd[1]: Reached target Sockets.
Nov 30 15:57:55 mrkline-arch systemd[1]: Starting Daily Cleanup of Temporary Directories.
Nov 30 15:57:55 mrkline-arch systemd[1]: Started Daily Cleanup of Temporary Directories.

Should I take that as an indication that it's something else? The config files in /usr/lib/tmpfiles.d  don't seem like anything out of the usual. Is there a way to get more verbosity out of the logs, or some other source?

Offline

#8 2013-12-01 00:51:22

WonderWoofy
Member
From: Los Gatos, CA
Registered: 2012-05-19
Posts: 8,414

Re: Unexplained boot delay due to I/O flood

See the man page for kernel-command-line.

Offline

#9 2013-12-10 23:48:02

slavik262
Member
From: WA, USA
Registered: 2012-07-12
Posts: 46
Website

Re: Unexplained boot delay due to I/O flood

Sorry for the delay, but I enabled systemd debug-level logging using parameter "systemd.log_level=debug". The updated sysemd-analyze plot (shown here) indicates that it is a tmpfiles issue. I'm still at a loss as to why, however - I didn't create any special tmpfiles myself, and all the ones there seem to do very little (certainly not enough to hang my system by 10-15 seconds).

The contents of the tmpfiles directory is displayed below - does anything look strange, or like it would take an inordinate amount of time?

# Comments stripped for brevity

d /run/console 0755 root root

x /run/user/*/gvfs
f /var/log/lastlog 0644 root root



d /run/lock 0755 root root -


d /run/lock/subsys 0755 root root -


d /run/lock/lockdev 0775 root lock -


r /forcefsck
r /fastboot
r /forcequotacheck
d /run/lock/lvm 0755 root root -
d /run/lvm 0755 root root -

d /run/nscd 0755 root root
D /run/svnserve 0700 root root -


d /run/user 0755 root root ~10d
F /run/utmp 0664 root utmp -

f /var/log/wtmp 0664 root utmp -
f /var/log/btmp 0600 root utmp -

d /var/cache/man - - - 30d

d /run/systemd/ask-password 0755 root root -
d /run/systemd/seats 0755 root root -
d /run/systemd/sessions 0755 root root -
d /run/systemd/users 0755 root root -
d /run/systemd/machines 0755 root root -
d /run/systemd/shutdown 0755 root root -

F /run/nologin 0644 - - - "System is booting up. See pam_nologin(8)"

m /var/log/journal 2755 root systemd-journal - -
m /var/log/journal/%m 2755 root systemd-journal - -


d /tmp 1777 root root 10d
d /var/tmp 1777 root root 30d

x /tmp/systemd-private-*
x /var/tmp/systemd-private-*
X /tmp/systemd-private-*/tmp
X /var/tmp/systemd-private-*/tmp
d /run/uuidd 0755 uuidd uuidd


d /tmp/.X11-unix 1777 root root 10d
d /tmp/.ICE-unix 1777 root root 10d
d /tmp/.XIM-unix 1777 root root 10d
d /tmp/.font-unix 1777 root root 10d
d /tmp/.Test-unix 1777 root root 10d

r /tmp/.X[0-9]*-lock

Last edited by slavik262 (2013-12-11 00:18:43)

Offline

#10 2014-01-25 16:04:30

potuz
Member
Registered: 2009-10-23
Posts: 112

Re: Unexplained boot delay due to I/O flood

Did you find a solution to your problem, I am experiencing the same (or very similar at least) problem on a clean stable Gentoo install. My systemd-analyze plot is here and the delay happens (on a log_level=debug boot) at update-utmp (after reaching the target timers on a normal boot).

Jan 25 12:27:49 birra systemd[1]: Child 2011 belongs to systemd-update-utmp.service
Jan 25 12:27:49 birra systemd[1]: systemd-update-utmp.service: main process exited, code=exited, status=0/SUCCESS
Jan 25 12:27:49 birra systemd[1]: systemd-update-utmp.service changed start -> exited
Jan 25 12:27:49 birra systemd[1]: Job systemd-update-utmp.service/start finished, result=done
Jan 25 12:27:49 birra systemd[1]: Started Update UTMP about System Reboot/Shutdown.
Jan 25 12:28:05 birra systemd[1]: Closed jobs progress timerfd.
Jan 25 12:28:05 birra systemd[1]: Starting System Initialization.
Jan 25 12:28:05 birra systemd[1]: sysinit.target changed dead -> active
Jan 25 12:28:05 birra systemd[1]: Job sysinit.target/start finished, result=done
Jan 25 12:28:05 birra systemd[1]: Reached target System Initialization.

Offline

#11 2014-01-25 16:58:24

GloW_on_dub
Member
Registered: 2013-03-13
Posts: 388

Re: Unexplained boot delay due to I/O flood

@potuz :  I'm sorry, but you should ask on gentoo forum.

Offline

#12 2014-04-08 16:27:31

slavik262
Member
From: WA, USA
Registered: 2012-07-12
Posts: 46
Website

Re: Unexplained boot delay due to I/O flood

I have two machines running Arch: A desktop with a traditional 7200 RPM spinning platter drive, and a laptop with a 16 GB SSD and a 7200 spinning drive. I'm utilizing the SSD using bcache.

Somehow my laptop with an SSD boots slower than my desktop without one. For whatever reason, midway through boot, something pegs the I/O light and the boot stops in its tracks for a good 15-20 seconds until the I/O subsides. Using systemd-analyze to try to get to the bottom of it is uesless, as the "culprit" changes every time. Sometimes there's even blank hole during the delay.

My guess is that this randomness is just due the I/O blockage stopping whatever poor init process happens to be running at the time, but then where the hell is this debilitating I/O coming from? Both machines have the same packages installed, give or take a random userspace application or two that would have nothing to do with booting. Bcache doesn't seem to be the issue since disabling SSD caching does absolutely nothing to alleviate the issue.

The really, really weird thing is that after a bad poweroff (i.e. a situation where it fsck's the disk), boot times are as-expected.

This has been going on for months, and while I can obviously live with it, it's extremely frustrating. Any and all help would be greatly appreciated.

I have done the following to debug the problem:

  • Used systemd-analyze to try to find the culprit process. As I said above, said "culprit" changes every time, and is often services that should take very little time. My guess is that this randomness is just due the I/O blockage stopping whatever poor init process happens to be running at the time.

  • Looked through the kernel logs, after setting the log level to debug. There's nothing unusual showing up there, and even more frustratingly, there are several-second gaps in the logs corresponding to when the delays occur. I wrote a quick program to find gaps in the log during boots and display the entries around the gaps. The resulting file can be found here.

Is there some way I could strace the entire boot sequence? That's the only thing I could think of doing next.

This is the same issue I posted about several months back, but didn't want to necro-bump that thread.

Last edited by slavik262 (2014-04-08 16:33:11)

Offline

#13 2014-04-08 17:26:17

Inxsible
Forum Fellow
From: Chicago
Registered: 2008-06-09
Posts: 9,183

Re: Unexplained boot delay due to I/O flood

slavik262 wrote:

This is the same issue I posted about several months back, but didn't want to necro-bump that thread.

Normally we allow threads to continue until the last post is more than a year old. Then it is considered old and we may close it without warning.

Your earlier thread was posted in late 2013. So it would be ok to continue there. I will merge your thread so that people have a context on what the issue is and what you have tried till now to fix it.


Forum Rules

There's no such thing as a stupid question, but there sure are a lot of inquisitive idiots !

Offline

Board footer

Powered by FluxBB