~90s delay before initramfs starts

eduncan911 · 2015-05-23 16:42:43

Hello:

I have updated to latest and the normal 4.0 kernel boots normally.

But, since I am in a VM I have a number of other kernels - and they have a significant 90 second+ delay before initramfs starts to boot.

I've narrowed it down by:

* installing kernel-lts
* removing all modules in mkinitpcio and rebuilding with -p linux-lts
* removed all options from the bootloader's options

$ cat /boot/loader/entries/arch-lts.conf 
title	Arch Linux (LTS)
linux	/vmlinuz-linux-lts
initrd	/initramfs-linux-lts.img
options	root=/dev/sda2 rw

$ head /etc/mkinitcpio.conf 
# vim:set ft=sh
# MODULES
# The following modules are loaded before any boot hooks are
# run.  Advanced users may wish to specify all system modules
# in this array.  For instance:
#     MODULES="piix ide_disk reiserfs"
#MODULES="vsock vmw_vsock_vmci_transport vmw_balloon vmw_vmci vmw_pvscsi vmxnet3"
# vmhgfs
MODULES=""

Immediately the system boots to the bootloader (Gummiboot, EFI). I select Arch (LTS) and the screen goes blank - for about 90 seconds. Then it boots normally.

Is there a way I can diagnosis this? Maybe there's a component on the initial start that hanging for 90s?

journalctl -xb didn't show anything. All time entires, even the first one, is 90 seconds after I selected the LTS kernel. Therefore, the delay is before journalctl is even logging the first entry.

Last edited by eduncan911 (2015-05-23 16:46:56)

Head_on_a_Stick · 2015-05-23 17:14:54

Please post the full content of /etc/mkinitcpio.conf

eduncan911 · 2015-05-23 17:17:42

here ya go. Humm, the "Hooks" line is interesting...

$ cat /etc/mkinitcpio.conf 
# vim:set ft=sh
# MODULES
# The following modules are loaded before any boot hooks are
# run.  Advanced users may wish to specify all system modules
# in this array.  For instance:
#     MODULES="piix ide_disk reiserfs"
#MODULES="vsock vmw_vsock_vmci_transport vmw_balloon vmw_vmci vmw_pvscsi vmxnet3"
# vmhgfs
MODULES=""

# BINARIES
# This setting includes any additional binaries a given user may
# wish into the CPIO image.  This is run last, so it may be used to
# override the actual binaries included by a given hook
# BINARIES are dependency parsed, so you may safely ignore libraries
BINARIES=""

# FILES
# This setting is similar to BINARIES above, however, files are added
# as-is and are not parsed in any way.  This is useful for config files.
FILES=""

# HOOKS
# This is the most important setting in this file.  The HOOKS control the
# modules and scripts added to the image, and what happens at boot time.
# Order is important, and it is recommended that you do not change the
# order in which HOOKS are added.  Run 'mkinitcpio -H <hook name>' for
# help on a given hook.
# 'base' is _required_ unless you know precisely what you are doing.
# 'udev' is _required_ in order to automatically load modules
# 'filesystems' is _required_ unless you specify your fs modules in MODULES
# Examples:
##   This setup specifies all modules in the MODULES setting above.
##   No raid, lvm2, or encrypted root is needed.
#    HOOKS="base"
#
##   This setup will autodetect all modules for your system and should
##   work as a sane default
#    HOOKS="base udev autodetect block filesystems"
#
##   This setup will generate a 'full' image which supports most systems.
##   No autodetection is done.
#    HOOKS="base udev block filesystems"
#
##   This setup assembles a pata mdadm array with an encrypted root FS.
##   Note: See 'mkinitcpio -H mdadm' for more information on raid devices.
#    HOOKS="base udev block mdadm encrypt filesystems"
#
##   This setup loads an lvm2 volume group on a usb device.
#    HOOKS="base udev block lvm2 filesystems"
#
##   NOTE: If you have /usr on a separate partition, you MUST include the
#    usr, fsck and shutdown hooks.
HOOKS="base udev autodetect modconf block filesystems keyboard fsck"

# COMPRESSION
# Use this to compress the initramfs image. By default, gzip compression
# is used. Use 'cat' to create an uncompressed image.
#COMPRESSION="gzip"
#COMPRESSION="bzip2"
#COMPRESSION="lzma"
#COMPRESSION="xz"
#COMPRESSION="lzop"
#COMPRESSION="lz4"
COMPRESSION="cat"

# COMPRESSION_OPTIONS
# Additional options for the compressor
#COMPRESSION_OPTIONS=""

But do note that the normal kernel with this mkinitpcio.conf works fine.

Last edited by eduncan911 (2015-05-23 17:18:48)

eduncan911 · 2015-05-23 17:21:24

If it matters, I did change my journalctl recently to keep previous boot messages.

Head_on_a_Stick · 2015-05-23 17:25:01

eduncan911 wrote:

the "Hooks" line is interesting

It's completely standard.

From a slow-booting system, post the output of:

systemd-analyze
systemd-analyze blame
systemd-analyze critical-chain

eduncan911 · 2015-05-23 17:28:23

whoa, those are cool commands...

$ systemd-analyze
Startup finished in 3.762s (firmware) + 2.937s (loader) + 1min 29.157s (kernel) + 1.973s (userspace) = 1min 37.831s

$ systemd-analyze blame
          1.158s dhcpcd@eno16777736.service
           340ms dkms.service
           221ms dev-sda2.device
            94ms packagekit.service
            66ms accounts-daemon.service
            59ms systemd-logind.service
            55ms systemd-journald.service
            53ms vmware-vmblock-fuse.service
            53ms systemd-user-sessions.service
            44ms polkit.service
            43ms systemd-vconsole-setup.service
            36ms systemd-udev-trigger.service
            34ms systemd-udevd.service
            32ms systemd-fsck@dev-disk-by\x2duuid-15FC\x2d2D3E.service
            29ms dev-mqueue.mount
            28ms tmp.mount
            27ms colord.service
            26ms dev-hugepages.mount
            25ms sys-kernel-config.mount
            22ms upower.service
            22ms kmod-static-nodes.service
            20ms systemd-sysctl.service
            20ms gdm.service
            19ms systemd-tmpfiles-clean.service
            17ms sys-kernel-debug.mount
            17ms systemd-remount-fs.service
            16ms user@120.service
            15ms systemd-tmpfiles-setup-dev.service
            15ms wpa_supplicant.service
            14ms udisks2.service
            12ms user@1000.service
             9ms boot.mount
             6ms systemd-tmpfiles-setup.service
             5ms systemd-journal-flush.service
             4ms systemd-random-seed.service
             3ms rtkit-daemon.service
             3ms systemd-update-utmp.service
             2ms systemd-rfkill@rfkill0.service
             1ms sys-fs-fuse-connections.mount

$ 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 @1.862s
└─multi-user.target @1.862s
  └─dhcpcd@eno16777736.service @704ms +1.158s
    └─sys-subsystem-net-devices-eno16777736.device @704ms

If I am reading this correctly, it's the kernel init?

Head_on_a_Stick · 2015-05-23 17:34:34

eduncan911 wrote:

If I am reading this correctly, it's the kernel init isn't it?

Fixed that for you

Yes, it looks like the delay is caused by the kernel.

How did you install the LTS kernel?

eduncan911 · 2015-05-23 17:39:06

Like normal, though I did get an error during mkinitcpio's rebuild which was caused by a VMware module I am having an issue with in other threads.

$ sudo pacman -S linux-lts

(OT: I did run pacman -Syu just before this and upgraded the system, which has a newer kernel released yesterday)

So I removed the module from mkinitcpio.conf, and re-installed it.

$ sudo pacman -S linux-lts

Which ran mkinitcpio normally. Still big delays.

i thought maybe something didn't work, so then I've ran mkinitcpio manually:

$ sudo mkinitcpio  -p linux-lts

Then I started disabling all modules, and made this thread...

Last edited by eduncan911 (2015-05-23 17:39:52)

Head_on_a_Stick · 2015-05-23 17:50:01

I've never actually used Arch in a VM so I probably won't be able to help much more, but you can try booting with systemd's debug options enabled in the kernel command-line:

systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M

https://wiki.archlinux.org/index.php/Sy … t_problems
http://freedesktop.org/wiki/Software/systemd/Debugging/

I'm not sure if this will actually produce any useful output as the problem seems to occur before systemd starts but you never know...

EDIT: There was a new version of the LTS kernel released just yesterday -- do you still have this problem if you downgrade the linux-lts package?

Last edited by Head_on_a_Stick (2015-05-23 17:52:31)

eduncan911 · 2015-05-23 18:39:51

Head_on_a_Stick wrote:

I've never actually used Arch in a VM so I probably won't be able to help much more, but you can try booting with systemd's debug options enabled in the kernel command-line:
systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M
https://wiki.archlinux.org/index.php/Sy … t_problems
http://freedesktop.org/wiki/Software/systemd/Debugging/
I'm not sure if this will actually produce any useful output as the problem seems to occur before systemd starts but you never know...
EDIT: There was a new version of the LTS kernel released just yesterday -- do you still have this problem if you downgrade the linux-lts package?

Debugging didn't seem to show anything meaningful (that was a lot). Like you said, it happens in the kernel before systemd.

I installed the previous version of the linux-lts package - and the same 90 second delay happens. No change.

Oh wells...

Arch Linux

#1 2015-05-23 16:42:43

~90s delay before initramfs starts

#2 2015-05-23 17:14:54

Re: ~90s delay before initramfs starts

#3 2015-05-23 17:17:42

Re: ~90s delay before initramfs starts

#4 2015-05-23 17:21:24

Re: ~90s delay before initramfs starts

#5 2015-05-23 17:25:01

Re: ~90s delay before initramfs starts

#6 2015-05-23 17:28:23

Re: ~90s delay before initramfs starts

#7 2015-05-23 17:34:34

Re: ~90s delay before initramfs starts

#8 2015-05-23 17:39:06

Re: ~90s delay before initramfs starts

#9 2015-05-23 17:50:01

Re: ~90s delay before initramfs starts

#10 2015-05-23 18:39:51

Re: ~90s delay before initramfs starts

Board footer