rootdelay= kernel command line arg results in sleep $ROOTDELAY in initramfs

Bug #1202700 reported by Scott Moser
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
systemd (Ubuntu)
Fix Released
Medium
Martin Pitt
Saucy
Fix Released
Medium
Martin Pitt

Bug Description

on azure saucy images (b39f27a8b8c64d52b05eac6a62ebad85__Ubuntu_DAILY_BUILD-saucy-13_10-amd64-server-20130718-en-us-30GB in 'US East' location). I get a 300 second timeout before / is mounted RW.

Resolution:
  This was not kernel related at all. It was related to a 'sleep $ROOTDELAY' in a initramfs script provided by ssytemd.

See attached dmesg for full dmesg. snippet here.
[ 6.974849] scsi3 : storvsc_host_t
[ 6.977249] scsi 3:0:1:0: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 4
[ 6.981087] sda: sda1
[ 6.983419] sd 3:0:1:0: Attached scsi generic sg2 type 0
[ 6.986119] sd 3:0:1:0: [sdb] 41943040 512-byte logical blocks: (21.4 GB/20.0 GiB)
[ 6.989874] sd 3:0:1:0: [sdb] Write Protect is off
[ 6.992325] sd 3:0:1:0: [sdb] Mode Sense: 0f 00 00 00
[ 6.992353] sd 2:0:0:0: [sda] Attached SCSI disk
[ 6.995243] sd 3:0:1:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[ 6.999603] scsi4 : storvsc_host_t
[ 7.002527] scsi scan: INQUIRY result too short (5), using 36
[ 7.006224] scsi scan: INQUIRY result too short (5), using 36
[ 7.009942] sdb: sdb1
[ 7.011837] scsi5 : storvsc_host_t
[ 7.015888] scsi scan: INQUIRY result too short (5), using 36
[ 7.019459] sd 3:0:1:0: [sdb] Attached SCSI disk
[ 7.022017] scsi scan: INQUIRY result too short (5), using 36
[ 303.184698] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
[ 305.379387] EXT4-fs (sda1): re-mounted. Opts: discard
---
AlsaDevices:
 total 0
 crw-rw---- 1 root audio 116, 1 Jul 18 14:08 seq
 crw-rw---- 1 root audio 116, 33 Jul 18 14:08 timer
AplayDevices: Error: [Errno 2] No such file or directory
ApportVersion: 2.11-0ubuntu1
Architecture: amd64
ArecordDevices: Error: [Errno 2] No such file or directory
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
CRDA: Error: command ['iw', 'reg', 'get'] failed with exit code 1: nl80211 not found.
CurrentDmesg: [ 356.806779] init: cloud-config main process (1126) terminated with status 1
DistroRelease: Ubuntu 13.10
IwConfig:
 eth0 no wireless extensions.

 lo no wireless extensions.
Lsusb: Error: command ['lsusb'] failed with exit code 1: unable to initialize libusb: -99
MachineType: Microsoft Corporation Virtual Machine
MarkForUpload: True
Package: linux (not installed)
PciMultimedia:

ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
ProcFB: 0 hyperv_fb
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.10.0-3-generic root=UUID=19f8b960-2ffd-4241-befd-fc605380cba6 ro console=tty1 console=ttyS0 earlyprintk=ttyS0 rootdelay=300
ProcVersionSignature: User Name 3.10.0-3.12-generic 3.10.1
RelatedPackageVersions:
 linux-restricted-modules-3.10.0-3-generic N/A
 linux-backports-modules-3.10.0-3-generic N/A
 linux-firmware 1.112
RfKill: Error: [Errno 2] No such file or directory
Tags: saucy uec-images
Uname: Linux 3.10.0-3-generic x86_64
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm audio cdrom dialout dip floppy netdev plugdev video
dmi.bios.date: 05/23/2012
dmi.bios.vendor: American Megatrends Inc.
dmi.bios.version: 090006
dmi.board.name: Virtual Machine
dmi.board.vendor: Microsoft Corporation
dmi.board.version: 7.0
dmi.chassis.asset.tag: 2175-9033-8610-7819-8007-6304-66
dmi.chassis.type: 3
dmi.chassis.vendor: Microsoft Corporation
dmi.chassis.version: 7.0
dmi.modalias: dmi:bvnAmericanMegatrendsInc.:bvr090006:bd05/23/2012:svnMicrosoftCorporation:pnVirtualMachine:pvr7.0:rvnMicrosoftCorporation:rnVirtualMachine:rvr7.0:cvnMicrosoftCorporation:ct3:cvr7.0:
dmi.product.name: Virtual Machine
dmi.product.version: 7.0
dmi.sys.vendor: Microsoft Corporation

Revision history for this message
Scott Moser (smoser) wrote :
Revision history for this message
Scott Moser (smoser) wrote : BootDmesg.txt

apport information

tags: added: apport-collected saucy uec-images
description: updated
Revision history for this message
Scott Moser (smoser) wrote : Lspci.txt

apport information

Revision history for this message
Scott Moser (smoser) wrote : ProcCpuinfo.txt

apport information

Revision history for this message
Scott Moser (smoser) wrote : ProcInterrupts.txt

apport information

Revision history for this message
Scott Moser (smoser) wrote : ProcModules.txt

apport information

Revision history for this message
Scott Moser (smoser) wrote : UdevDb.txt

apport information

Revision history for this message
Scott Moser (smoser) wrote : UdevLog.txt

apport information

Revision history for this message
Scott Moser (smoser) wrote : WifiSyslog.txt

apport information

Revision history for this message
Brad Figg (brad-figg) wrote : Status changed to Confirmed

This change was made by a bot.

Changed in linux (Ubuntu):
status: New → Confirmed
Revision history for this message
Ben Howard (darkmuggle-deactivatedaccount) wrote : Re: saucy kernel 300 second hang before root mounted rw on azure

Previously MS asked for us to include "rootdelay=300". Removing "rootdelay=..." results in a machine that boots in ~15s.

utlemming@utl-0718-a:~$ dmesg | head -n10
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 3.10.0-3-generic (buildd@roseapple) (gcc version 4.8.1 (Ubuntu/Linaro 4.8.1-6ubuntu1) ) #12-Ubuntu SMP Mon Jul 15 16:47:40 UTC 2013 (Ubuntu 3.10.0-3.12-generic 3.10.1)
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.10.0-3-generic root=UUID=19f8b960-2ffd-4241-befd-fc605380cba6 ro console=tty1 console=ttyS0 earlyprintk=ttyS0 debug
[ 0.000000] KERNEL supported cpus:
[ 0.000000] Intel GenuineIntel
[ 0.000000] AMD AuthenticAMD
[ 0.000000] Centaur CentaurHauls
[ 0.000000] e820: BIOS-provided physical RAM map:
utlemming@utl-0718-a:~$ dmesg | tail -n10
[ 13.179617] init: plymouth-upstart-bridge main process (969) terminated with status 1
[ 13.530699] type=1400 audit(1374160837.852:8): apparmor="STATUS" operation="profile_replace" parent=1037 profile="unconfined" name="/sbin/dhclient" pid=1042 comm="apparmor_parser"
[ 13.530710] type=1400 audit(1374160837.852:9): apparmor="STATUS" operation="profile_replace" parent=1037 profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1042 comm="apparmor_parser"
[ 13.530715] type=1400 audit(1374160837.852:10): apparmor="STATUS" operation="profile_replace" parent=1037 profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=1042 comm="apparmor_parser"
[ 13.531340] type=1400 audit(1374160837.852:11): apparmor="STATUS" operation="profile_replace" parent=1037 profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1042 comm="apparmor_parser"
[ 14.025059] hv_utils: KVP: user-mode registering done.
[ 14.459850] init: plymouth-stop pre-start process (1175) terminated with status 1
[ 15.211528] psmouse serio1: trackpoint: IBM TrackPoint firmware: 0x01, buttons: 0/0
[ 15.212311] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/input/input3
[ 15.593280] EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)

Changed in linux (Ubuntu):
importance: Undecided → Medium
tags: added: kernel-da-key
Revision history for this message
Ben Howard (darkmuggle-deactivatedaccount) wrote :

To clarify, this is a boot regression from 13.04 to 13.10. On previous versions it takes a few seconds (~15 to ~20) to boot completely.

Revision history for this message
Joseph Salisbury (jsalisbury) wrote :

I'd like to perform a bisect to figure out what commit caused this regression. We need to identify the earliest kernel where the issue started happening as well as the latest kernel that did not have this issue.

Can you test the following kernels and report back? We are looking for the first kernel version that exhibits this bug:

3.8 final: http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.8-raring/
v3.9 final: http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.9-saucy
v3.10-rc1: http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.10-rc1-saucy/

You don't have to test every kernel, just up until the kernel that first has this bug. I don't expect 3.8 final to exhibit the bug, but it would be good to test 3.8 on a Saucy install to confirm the issue is in the kernel.

Thanks in advance!

tags: added: regression-release
tags: added: performing-bisect
Revision history for this message
Ben Howard (darkmuggle-deactivatedaccount) wrote :

Problematic commit was revno 31.

------------------------------------------------------------
revno: 31
tags: 202-0ubuntu10
fixes bug: https://launchpad.net/bugs/1185060
author: Martin Pitt <email address hidden>
committer: Package Import Robot <email address hidden>
branch nick: saucy-proposed
timestamp: Wed 2013-05-29 10:12:35 +0200
message:
  * debian/extra/initramfs.bottom: Drop reading of /etc/udev/udev.conf, the
    location of /dev hasn't been configurable for ages.
  * debian/extra/initramfs.top: Drop obsolete "scsi_wait_scan" modprobing here
    as well.
  * all_generic_ide blacklist: Depend on "all_generic_ide blacklist", as in
    previous udev.
  * debian/extra/initramfs.top: Drop unnecessary "udevadm settle".
  * debian/extra/initramfs.hook: Put back ata_id and scsi_id, these were
    overzealously removed with the bits that are built in now (like blkid and
    usb_id). LP: #1185060
  * debian/extra/udev.startup: Drop devpts mounting again, already done by
    /usr/share/initramfs-tools/init.
  * debian/extra/initramfs.hook: Install udevadm.upgrade when updating the
    initramfs while udev is unconfigured.
  * debian/extra/initramfs.hook: Remove duplicate copying of
    70-persistent-net.rules.
  * debian/extra/initramfs.hook: Don't install the dmsetup and md rules. This
    is already done by dmsetup's and mdadm's initramfs hooks.
diff:
=== modified file 'debian/extra/initramfs.top'
--- debian/extra/initramfs.top 2013-03-13 10:46:40 +0000
+++ debian/extra/initramfs.top 2013-05-29 08:12:35 +0000
@@ -1,6 +1,6 @@
 #!/bin/sh -e

-PREREQS=""
+PREREQS="all_generic_ide blacklist"

 prereqs() { echo "$PREREQS"; }

@@ -13,16 +13,9 @@

 echo > /sys/kernel/uevent_helper

-UDEV_ROOT=/dev \
 /lib/systemd/systemd-udevd --daemon --resolve-names=never

 udevadm trigger --action=add
-udevadm settle || true
-
-if [ -d /sys/bus/scsi ]; then
- modprobe -q scsi_wait_scan && modprobe -r scsi_wait_scan || true
- udevadm settle || true
-fi

 # If the rootdelay parameter has been set, we wait a bit for devices
 # like usb/firewire disks to settle.

Revision history for this message
Martin Pitt (pitti) wrote :

Committed to local packaging git. Will do an upload tomorrow, as I plan some (unrelated) logind debugging/fixing tomorrow.

affects: linux (Ubuntu Saucy) → systemd (Ubuntu Saucy)
Changed in systemd (Ubuntu Saucy):
assignee: nobody → Martin Pitt (pitti)
status: Confirmed → In Progress
status: In Progress → Fix Committed
Scott Moser (smoser)
description: updated
Scott Moser (smoser)
summary: - saucy kernel 300 second hang before root mounted rw on azure
+ rootdelay= kernel command line arg results in sleep $ROOTDELAY in
+ initramfs
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package systemd - 204-0ubuntu7

---------------
systemd (204-0ubuntu7) saucy; urgency=low

  * debian/tests/control: Add missing pkg-config test dependency, drop
    unnecessary python3 dependency.
 -- Martin Pitt <email address hidden> Fri, 19 Jul 2013 11:38:40 +0200

Changed in systemd (Ubuntu Saucy):
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.