5-10 second delay in kernel boot with kernel command line ip=

[Alkis Georgopoulos]

In Trusty I see a big delay while the kernel boots that I did not see back in Precise.
Some people have been experiencing this in Saucy too, so I don't know exactly when it started happening.
Excerpt from dmesg:
[ 3.740100] Switched to clocksource tsc
[ 14.208118] PM: Hibernation image not present or could not be loaded.
[ 14.208885] Freeing unused kernel memory: 864K (c19ac000 - c1a84000)

The exact messages above don't matter, they are different on different boots or on different machines.
It even happens with e.g.
$ sudo kvm -m 768 -cdrom trusty-desktop-i386.iso

My current kernel is
Linux server 3.12.0-7-generic #15-Ubuntu SMP Sun Dec 8 23:42:09 UTC 2013 i686 i686 i686 GNU/Linux
...but the exact version, maybe from 3.8 to 3.12+, shouldn't matter, just run `dmesg` yourself and check if there's a big delay there.

[Brad Figg (brad-figg)]

This bug is missing log files that will aid in diagnosing the problem. From a terminal window please run:

apport-collect 1259861

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Alkis Georgopoulos (alkisg)]

...ignoring the bot and changing the state back to New, as the exact kernel version doesn't matter...

[Brad Figg (brad-figg)]

This bug is missing log files that will aid in diagnosing the problem. From a terminal window please run:

apport-collect 1259861

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Alkis Georgopoulos (alkisg)]

Changing to confirmed to satisfy the bot. :)

[Joseph Salisbury (jsalisbury)]

Would it be possible for you to test the latest upstream kernel? Refer to https://wiki.ubuntu.com/KernelMainlineBuilds . Please test the latest v3.12 kernel[0].

If this bug is fixed in the mainline kernel, please add the following tag 'kernel-fixed-upstream'.

If the mainline kernel does not fix this bug, please add the tag: 'kernel-bug-exists-upstream'.

If you are unable to test the mainline kernel, for example it will not boot, please add the tag: 'kernel-unable-to-test-upstream'.
Once testing of the upstream kernel is complete, please mark this bug as "Confirmed".

Thanks in advance.

[0] http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.13-rc3-trusty/

[Alkis Georgopoulos (alkisg)]

I just tested with linux-image-3.13.0-031300rc3-generic_3.13.0-031300rc3.201312061335_i386.deb, it doesn't happen there.

I don't think I should put the 'kernel-fixed-upstream' tag as the problem might be in some Ubuntu-specific kernel patch or configuration option that's been around for a couple of years.

Do you want me to test with the vanilla 3.12 too? The delay probably won't exist there either...

[Joseph Salisbury (jsalisbury)]

Sure, it would be good to know if this is related to an Ubuntu specific patch. Can you test the upstream 3.12.4 kernel:

http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.12.4-trusty/

[Launchpad Janitor (janitor)]

[Expired for linux (Ubuntu) because there has been no activity for 60 days.]

[Alkis Georgopoulos (alkisg)]

I think anyone can just run `dmesg` and verify that the bug exists in all recent Ubuntu kernels and in none of the vanilla or Debian kernels.
I don't know why the logs are important here.
I don't think there's any point in closing bugs just to lower the bug count (which means nothing if the bugs are still there), instead of running a single command to verify them.

[Alkis Georgopoulos (alkisg)]

@penlalvch: I was asked in #ubuntu-kernel to file this bug report so that they can assign someone to work on it.

If you keep adding "it needs this and that" tags, then this bug report appears to be incomplete, and no developer will start working on it until I satisfy/remove the tags.

But as I keep saying,
1) needs-apport-collect => why? it happens anywhere, so I could run apport-collect in a KVM VM, but why would anyone want that? It's just useless information.
2) needs-upstream-testing => as I said, the problem doesn't happen in any Debian or Vanilla kernels.
OK if you really need a specific version there, here it is:
$ uname -a
Linux alkis 3.13.0-9.29-031400rc3-generic #201402181344 SMP Tue Feb 18 19:02:54 UTC 2014 i686 i686 i686 GNU/Linux
...but again that version number is useless because it doesn't happen in _any_ vanilla kernels.

[Alkis Georgopoulos (alkisg)]

@penalvch: as I mention in comment #6, the "kernel-fixed-upstream" tag is not appropriate because this was never an upstream bug, so nothing was fixed upstream. It's an ubuntu-specific bug, so upstream is not related at all to this bug and shouldn't appear in any tags.

The "needs-kernel-logs" tag also isn't appropriate because it's useless information, anyone willing to work on this can just check the logs on his own pc.

Karma points are nice, but they shouldn't be a goal... If you really want to help, do so by triaging bugs, not by tagging them...

[Joseph Salisbury (jsalisbury)]

Thank you for taking the time to file a bug report on this issue.

However, given the number of bugs that the Kernel Team receives during any development cycle it is impossible for us to review them all. Therefore, we occasionally resort to using automated bots to request further testing. This is such a request.

  With the recent release of this Ubuntu release, would like to confirm if this bug is still present. Please test again with the newer kernel and indicate in the bug if this issue still exists or not.

You can update to the latest development kernel by simply running the following commands in a terminal window:

    sudo apt-get update
    sudo apt-get dist-upgrade

If the bug still exists, change the bug status from Incomplete to Confirmed. If the bug no longer exists, change the bug status from Incomplete to Fix Released.

If you want this bot to quit automatically requesting kernel tests, add a tag named: bot-stop-nagging.

 Thank you for your help, we really do appreciate it.

[Alkis Georgopoulos (alkisg)]

Yes it's still happening on 3.13.0-29-generic.

[ 3.912539] random: nonblocking pool is initialized
[ 19.999335] Adding 3957756k swap on /dev/sda7. Priority:-1 extents:1 across:3957756k FS

[Richard Hansen (rhansen)]

I have been seeing this on multiple machines since trusty (at least). I'm currently running wily.

I noticed that if I remove the 'ip=dhcp' kernel command line parameter then the 10 second delay goes away. (I added ip=dhcp so that I could ssh into the initramfs to unlock the encrypted root device from remote.) I'm not sure why 'ip=dhcp' causes that delay. I was able to rule out the initramfs—I modified /usr/share/initramfs-tools/init to print the contents of /proc/uptime as early as possible. According to the logged time, init doesn't start running until after the 10 second pause (unless mounting /proc takes 10 seconds when ip=dhcp is in the command line arguments, which I doubt).

[Alkis Georgopoulos (alkisg)]

@rhansen, your bug might be a different one, since ip=dhcp is processed by the initramfs, while I'm talking about the kernel, before the initramfs gets to run.

The bug is still there in Xenial.
I noticed that it doesn't happen in all hardware; I've seen it in *some* real clients and under VirtualBox, while I haven't been able to reproduce it under KVM.

Example from Xenial:
$ grep 'model name' /proc/cpuinfo
model name : Intel(R) Core(TM) i5-4590 CPU @ 3.30GHz

$ dmesg
...
[ 1.224044] usb 3-4: ep 0x81 - rounding interval to 64 microframes, ep desc says 80 microframes
[ 1.677095] tsc: Refined TSC clocksource calibration: 3292.375 MHz
[ 1.677134] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2f75298baf3, max_idle_ns: 440795322961 ns
[ 2.677286] clocksource: Switched to clocksource tsc
[ 12.784911] PM: Hibernation image not present or could not be loaded.
[ 12.785223] Freeing unused kernel memory: 936K (c1b6d000 - c1c57000)
[ 12.785350] Write protecting the kernel text: 7816k
[ 12.785450] Write protecting the kernel read-only data: 3120k
[ 12.785502] NX-protecting the kernel data: 6520k
[ 12.797220] random: systemd-udevd urandom read with 0 bits of entropy available
...

I also tried with "nohibernate", it's not related to hibernation.

[Alkis Georgopoulos (alkisg)]

@rhansen, sorry, it turns out you were right!

ip= is what's causing my kernel delay. I even tried without an initramfs to verify it, and it caused 10 seconds of delay before the kernel panic because of the missing initramfs.

I'll try to gather more info about it.

[TJ (tj)]

Try adding kernel command-line dynamic debug option:

 ... "dyndbg=file net/ipv4/ipconfig.c +pflm" ...

[Richard Hansen (rhansen)]

> Try adding kernel command-line dynamic debug option:
>
> ... "dyndbg=file net/ipv4/ipconfig.c +pflm" ...

I added:

    dyndbg="file net/ipv4/ipconfig.c +pflm"

to the end of the kernel command line arguments in grub and removed quiet. After booting I ran 'dmesg >after.txt'. I then rebooted and this time only removed the quiet argument, then ran 'dmesg >before.txt'. After stripping the timestamp column I diffed before.txt and after.txt and there was no new information (not even a line saying that the dyndbg was enabled).

Perhaps this is because the kernel image is stripped?

[Richard Hansen (rhansen)]

I installed a vanilla 4.5 kernel, which has this debug logging change:

https://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/net/ipv4/ipconfig.c?id=09605cc12c07830659a19b266503795c511a2060

After booting with the dyndbg argument, the only new output is this:

[ 1.079405] ipconfig:ip_auto_config:1417: IP-Config: Entered.

That line is printed before the delay. There are no other new debug lines from ipconfig.c.

[Richard Hansen (rhansen)]

After studying the code in net/ipv4/ipconfig.c I'm fairly confident
that the problem is caused by wait_for_devices() failing to find any
network interfaces and timing out. That function waits for 12 seconds
before giving up, and the time difference between the "IP-Config:
Entered" message and the end of the delay is just a hair over 12
seconds.

It makes sense that wait_for_devices() would fail: There are no
network devices until the initramfs loads the network interface
modules, and the initramfs init script doesn't start running until
after the kernel is done processing the ip=* argument.

So if the kernel fails to handle the ip=* argument, how does the ip=*
parameter work at all? The answer is the initramfs: The initramfs
init script parses the ip command-line argument and the
scripts/functions script runs the ipconfig utility with the
appropriate arguments to configure the interface.

I see a few ways to fix this:
  * Modify the kernel source code to provide a way to change/disable
    the timeout.
  * Modify the kernel source code to allow the initramfs to load while
    the kernel is still waiting for a network device to appear.
  * Compile all network drivers into the kernel itself (don't build
    them as modules).
  * Modify the initramfs init script to introduce an alias for the
    ip=* parameter, e.g., initramfs_ip=*. This would allow users to
    avoid the pointless kernel processing.

The last option is probably the easiest and least likely to introduce
any unintended side effects.

[Alkis Georgopoulos (alkisg)]

The problem is not there in Ubuntu 12.04.2 (kernel 3.5.0-54)
and it is there in Ubuntu 12.04.3 (kernel 3.8.0-44).

My test case is to boot with ip=dhcp break=top. When the problem doesn't exist, I get an initramfs prompt in 2 seconds, when it exists I get it in 12 seconds, and that shows up in dmesg as well.

Comparing those configs from https://wiki.ubuntu.com/Kernel/Configs/QuantalToRaring, I got:
3.5: # CONFIG_IP_PNP is not set
3.8: CONFIG_IP_PNP=y CONFIG_IP_PNP_DHCP=y

Is it possible to revert those?
Can we find out why they were enabled?
If they're only needed on some arches (e.g. ARM), maybe they could only be enabled there?

@rhansen, writing an alias e.g. initramfs_ip=* won't help, e.g. IPAPPEND 3 in pxelinux puts ip=* in the cmdline, I don't think it'll ever be patched to put initramfs_ip=* there...
I think we should either get the configuration change reverted,
or fix ipconfig.c so that it aborts if no NICs/modules are detected.

[Richard Hansen (rhansen)]

I have uploaded some modified initramfs-tools packages to my PPA:

https://launchpad.net/~rhansen/+archive/ubuntu/bug1259861

With the version in my PPA, the initramfs init script now has a new
initramfs_ip parameter in addition to the existing ip parameter. The
initramfs treats the initramfs_ip parameter the same as the ip
parameter. Using initramfs_ip=* instead of ip=* avoids the 12 second
kernel delay that comes from the kernel processing the ip=* parameter.

To eliminate the boot delay:
  1. run:
         sudo apt-add-repository ppa:rhansen/bug1259861
         sudo apt-get update
         sudo apt-get dist-upgrade
  2. edit /etc/default/grub and change your ip=* argument to
     initramfs_ip=*
  3. run:
         sudo update-grub

[Alkis Georgopoulos (alkisg)]

I think the upstream commit that set CONFIG_IP_PNP=y is this:
https://github.com/torvalds/linux/commit/c1b362e3b4d331a63915b268a33207311a439d60#diff-364c3610ebc6899c22148ba10636c71c

Ubuntu and openSUSE now have CONFIG_IP_PNP=y and experience the issue.
Debian and Fedora do not have CONFIG_IP_PNP set and do not experience the issue.

To reproduce in different distros, set `ip=dhcp init=/bin/sh` and see if getting a prompt takes longer than 10+ seconds or not.

[Richard Hansen (rhansen)]

Yes, I think the change to CONFIG_IP_PNP=y is what caused this problem. If you look in net/ipv4/Makefile, you'll see this line:

    obj-$(CONFIG_IP_PNP) += ipconfig.o

If CONFIG_IP_PNP is not set to y, then all of net/ipv4/ipconfig.c is excluded from the resulting kernel. That file contains the code that causes the delay.

Given that ipconfig.c is useless without a network interface (right?) and most network device drivers are built as modules (right?) and the modules are loaded after the ip=* argument is processed by the kernel, then perhaps it does make sense to undefine CONFIG_IP_PNP. Enabling it doesn't provide any benefit unless the network device drivers are built into the kernel (not as modules).

[Andy Whitcroft (apw)]

Ok it sounds liek we have two implementations of the ip= option, one in the kernel and one in initramfs-tools. As we load the majority of network drivers from the initramfs it does not seem logical to waste time in the kernel attempting this there when on average we do not have the required drivers and cannot load them until the initramfs starts. Assuming we have feature parity in userspace we should disable this. Will investigate.

[TJ (tj)]

Originally introduced into the Ubuntu 13.10 (Saucy) configuration with commit 301b4bb

commit 301b4bb24cf60f339643ffddbd630169e488adf2
Author: Leann Ogasawara <email address hidden>
Date: Fri Mar 12 17:13:25 2010 -0800

    UBUNTU: rebase to v3.10-rc4

    Signed-off-by: Andy Whitcroft <email address hidden>

$ git show 301b4bb | awk '/^\+\+\+/{FILE=$0} /^[-+]CONFIG_IP_PNP=/ {print FILE; print}'
+++ b/debian.master/config/config.common.ubuntu
+CONFIG_IP_PNP=y

[Andy Whitcroft (apw)]

For Xenial it looks very much like the initramfs is feature equivalent to the kernel support (this may be no accident).

[Andy Whitcroft (apw)]

Indeed it appears that the initramfs is feature equivalent for all releases back to Trusty (where this was first enabled). It seems sensible to turn this off. However, lets do that in xenial first and look for fallout.

[Alkis Georgopoulos (alkisg)]

> TJ (tj) wrote 9 hours ago: #26
> Originally introduced into the Ubuntu 13.10 (Saucy) configuration with commit 301b4bb
> UBUNTU: rebase to v3.10-rc4

TJ, that doesn't match my tests as mentioned in comment #21,
i.e. that I see the issue since kernel 3.8, and that
https://wiki.ubuntu.com/Kernel/Configs/QuantalToRaring says the change was done in Raring.

A `grep IP_PNP /boot/config*` in a 3.8 kernel does verify that the change was done before 3.10 (or backported in 3.8? dunno).

[Alkis Georgopoulos (alkisg)]

$ for d in karmic lucid maverick natty oneiric precise quantal raring saucy trusty utopic vivid wily xenial; do
    echo "$d: $(wget -q http://kernel.ubuntu.com/~kernel-ppa/configs/$d/i386-config.flavour.generic -O - | grep -w CONFIG_IP_PNP)"
done

karmic:
lucid:
maverick:
natty: # CONFIG_IP_PNP is not set
oneiric: # CONFIG_IP_PNP is not set
precise: # CONFIG_IP_PNP is not set
quantal: # CONFIG_IP_PNP is not set
raring: CONFIG_IP_PNP=y
saucy: CONFIG_IP_PNP=y
trusty: CONFIG_IP_PNP=y
utopic: CONFIG_IP_PNP=y
vivid: CONFIG_IP_PNP=y
wily: CONFIG_IP_PNP=y
xenial:

[Alkis Georgopoulos (alkisg)]

apw uploaded a test kernel without CONFIG_IP_PNP in http://people.canonical.com/~apw/lp1259861-xenial/.
I tested it with "ip=dhcp break=top" and it didn't have the 10 sec delay.

Thanks a lot Andy!

[Launchpad Janitor (janitor)]

This bug was fixed in the package linux - 4.4.0-16.32

---------------
linux (4.4.0-16.32) xenial; urgency=low

  [ Tim Gardner ]

  * Release Tracking Bug
    - LP: #1561727

  * fix thermal throttling due to commit "Thermal: initialize thermal zone
    device correctly" (LP: #1561676)
    - Thermal: Ignore invalid trip points

  * Thinkpad T460: Trackpoint mouse buttons instantly generate "release" event
    on press (LP: #1553811)
    - SAUCE: (noup) Input: synaptics - handle spurious release of trackstick
      buttons, again

  * reading /sys/kernel/security/apparmor/profiles requires CAP_MAC_ADMIN
    (LP: #1560583)
    - SAUCE: apparmor: Allow ns_root processes to open profiles file
    - SAUCE: apparmor: Consult sysctl when reading profiles in a user ns

  * linux: sync virtualbox drivers to 5.0.16-dfsg-2 (LP: #1561492)
    - ubuntu: vbox -- update to 5.0.16-dfsg-2

  * s390/kconfig: CONFIG_NUMA without CONFIG_NUMA_EMU does not make any sense on
    s390x (LP: #1557690)
    - [Config] CONFIG_NUMA_BALANCING_DEFAULT_ENABLED=n for s390x

  * spl/zfs fails to build on s390x (LP: #1519814)
    - [Config] s390x -- re-enable zfs
    - [Config] zfs -- disable powerpc until the test failures can be resolved

  * linux: sync to ZFS 0.6.5.6 stable release (LP: #1561483)
    - SAUCE: (noup) Update spl to 0.6.5.6-0ubuntu1, zfs to 0.6.5.6-0ubuntu1

  * zfs: enable zfs for 64bit powerpc kernels (LP: #1558871)
    - [Packaging] zfs -- handle rprovides via dpkg-gencontrol
    - [Config] powerpc -- convert zfs configuration to custom_override

  * Memory arena corruption with FUSE (was Memory allocation failure crashes
    kernel hard, presumably related to FUSE) (LP: #1505948)
    - SAUCE: (noup) fuse: do not use iocb after it may have been freed
    - SAUCE: (noup) fuse: Add reference counting for fuse_io_priv

  * cgroup namespaces: add a 'nsroot=' mountinfo field (LP: #1560489)
    - SAUCE: (noup) cgroup namespaces: add a 'nsroot=' mountinfo field

  * linux packaging: clear remaining redundant delta (LP: #1560445)
    - [Debian] Remove generated intermediate files on clean

  * arm64: guest hangs when ntpd is running (LP: #1549494)
    - Revert "hrtimer: Add support for CLOCK_MONOTONIC_RAW"
    - Revert "hrtimer: Catch illegal clockids"
    - Revert "KVM: arm/arm64: timer: Switch to CLOCK_MONOTONIC_RAW"

  * Need enough contiguous memory to support GICv3 ITS table (LP: #1558828)
    - [Config] CONFIG_FORCE_MAX_ZONEORDER=13 on arm64
    - SAUCE: (no-up) arm64: gicv3: its: Increase FORCE_MAX_ZONEORDER for Cavium
      ThunderX

  * update arcmsr to version v1.30.00.22-20151126 to fix card timeouts
    (LP: #1559609)
    - arcmsr: fixed getting wrong configuration data
    - arcmsr: fixes not release allocated resource
    - arcmsr: make code more readable
    - arcmsr: adds code to support new Areca adapter ARC1203
    - arcmsr: changes driver version number
    - arcmsr: more readability improvements
    - arcmsr: Split dma resource allocation to a new function
    - arcmsr: change driver version to v1.30.00.22-20151126

  * server image has no keyboard, desktop image works (LP: #1559692)
    - [Config] Rework input-modules (d-i) list

  * PMU sup...