[2.6.32-11 regression] 5 second delay on early boot during usb_id

Bug #510937 reported by Martin Pitt on 2010-01-21
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
linux (Ubuntu)
Medium
Andy Whitcroft
Lucid
Medium
Andy Whitcroft
udev (Ubuntu)
Undecided
Unassigned
Lucid
Undecided
Unassigned

Bug Description

Since the update to 2.6.32-11 from -10, usb_id hangs for 5 seconds. Compare

  http://people.canonical.com/~pitti/bootcharts/daniel-lucid-20100121-1.png (2.6.32-10)

with

  http://people.canonical.com/~pitti/bootcharts/daniel-lucid-20100122-1.png (2.6.32-11)

This is both on current lucid on the same machine (Dell Mini 10 SSD, reference platform for boot speed goal).

I haven't investigated yet whether this is really a kernel regression or a previously hidden bug in usb_id/udev.

ProblemType: Bug
AlsaVersion: Advanced Linux Sound Architecture Driver Version 1.0.21.
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC1: martin 2712 F.... pulseaudio
 /dev/snd/controlC0: martin 2712 F.... pulseaudio
CRDA: Error: [Errno 2] No such file or directory
Card0.Amixer.info:
 Card hw:0 'Intel'/'HDA Intel at 0xefebc000 irq 21'
   Mixer name : 'SigmaTel STAC9200'
   Components : 'HDA:83847690,10280201,00102201'
   Controls : 7
   Simple ctrls : 5
Card1.Amixer.info:
 Card hw:1 'Headset'/'Logitech Logitech USB Headset at usb-0000:00:1d.7-8.3.4, full speed'
   Mixer name : 'USB Mixer'
   Components : 'USB046d:0a01'
   Controls : 6
   Simple ctrls : 2
Date: Fri Jan 22 00:21:54 2010
DistroRelease: Ubuntu 10.04
EcryptfsInUse: Yes
HibernationDevice: RESUME=UUID=96523246-f56d-4385-a46f-292cefc7a970
MachineType: Dell Inc. Latitude D430
Package: linux-image-2.6.32-11-generic 2.6.32-11.15
ProcCmdLine: BOOT_IMAGE=/boot/vmlinuz-2.6.32-11-generic root=UUID=c58ab6de-7f75-4e41-9888-2a9338bd55c6 ro quiet splash
ProcEnviron:
 PATH=(custom, user)
 LANG=de_DE.utf8
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.32-11.15-generic
Regression: Yes
RelatedPackageVersions: linux-firmware 1.28
Reproducible: Yes
SourcePackage: linux
TestedUpstream: No
Uname: Linux 2.6.32-11-generic x86_64
dmi.bios.date: 05/21/2007
dmi.bios.vendor: Dell Inc.
dmi.bios.version: A00
dmi.board.name: 0HU754
dmi.board.vendor: Dell Inc.
dmi.chassis.type: 8
dmi.chassis.vendor: Dell Inc.
dmi.modalias: dmi:bvnDellInc.:bvrA00:bd05/21/2007:svnDellInc.:pnLatitudeD430:pvr:rvnDellInc.:rn0HU754:rvr:cvnDellInc.:ct8:cvr:
dmi.product.name: Latitude D430
dmi.sys.vendor: Dell Inc.

Martin Pitt (pitti) wrote :
Changed in linux (Ubuntu):
importance: Undecided → High
Martin Pitt (pitti) wrote :

I had a first quick look at this, and it doesn't reproduce with udevadm trigger in the booted system, and not even with init=/bin/bash and starting udev/udevadm trigger manually.

description: updated
Martin Pitt (pitti) wrote :

I took a look at the three udev rules in the initramfs that use usb_id:

 * We do not need the hplip permission one from 50-udev-default.rules at all; it will be caught by the udevadm trigger in the real system

 * I am pretty sure that we do not need a /dev/disks/by-id/ symlink in the initramfs. We only support UUIDs for file systems, which are generated by blkid, not usb_id.

Thus I jsut removed copying usb_id into the initramfs by commenting out the line in /usr/share/initramfs-tools/hooks/udev. This might be worth doing either way, since it speeds up the time spent in initramfs?

When I do that, I do not get the early 5 s khubd/usb_id blocking any more, and the total boot time again drops from 20 to 15 seconds (just with kernel 2.6.32-10). Instead, I now get a 2.5 s usb_id process hanging off the /etc/init/udevtrigger.conf tree, presumably on the same problematic device. However, it does not slow down the boot any more.

Martin Pitt (pitti) wrote :

http://people.canonical.com/~pitti/bootcharts/daniel-lucid-20100201-no-initramfs-usb_id.png is the associated bootchart with dropping usb_id from initramfs.

Martin Pitt (pitti) wrote :

Discussed with Scott, and we do support booting with by-id symlinks, thus we need to keep usb_id in the initramfs.

Changed in udev (Ubuntu Lucid):
status: New → Won't Fix
Changed in udev (Ubuntu):
status: New → Won't Fix
Stefan Bader (smb) on 2010-02-05
Changed in linux (Ubuntu Lucid):
importance: High → Medium
status: New → Confirmed
Andy Whitcroft (apw) wrote :

Ok, I have just discovered that this usb-id is much much quicker, of the order of 0.2s if there is an MMC card in the slot on the machine (Dell mini 10v). Remove it and its back to 5s.

Changed in linux (Ubuntu Lucid):
assignee: nobody → Andy Whitcroft (apw)
Andy Whitcroft (apw) wrote :

Ok I have isolated this to new locking in the sysfs file read code. This seems to be necessary locking as there was a chance that the values being read could be freed underneath us. Contention between usb_id and khubd (presumably) scanning the hub leads to extended waits usb_id trying to aquire the usb device semaphore. We could probabally fix this by converting the update of these values to rcu but that would require fixing all of those sharing the sysfs code, which appears to be all usb devices.

So the key question is, Is the delay on usb_id actually causing an issue here now that we are not blocking on it?

Martin Pitt (pitti) wrote :

> So the key question is, Is the delay on usb_id actually causing an issue here now that we are not blocking on it?

The extra I/O wait/process blocking/etc now costs us .3 seconds (averaged over three reboots, between lucid current and lucid current userspace with -10 kernel, and looked at time until when gdm starts).

So it's certainly small enough to not warrant rewriting the entire subsytem :-)

As discussed on IRC, there are many instances where we *will* block on it - there's still a udevadm settle in the boot, it's just later than usual.

This will add 5s to the boot of any non-KMS machine, any machine with encrypted disks, etc.

While that's not our "reference image", it's an important enough set of users that this does need to be fixed

Andy Whitcroft (apw) wrote :

Ok testing seems to indicate that there is a .3s general benefit for fixing this for the reference platform. There is also a high probabality of a multi second delay for a large userbase so this seems worth fixing. Testing of some RCU patches is in progress.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package linux - 2.6.32-14.20

---------------
linux (2.6.32-14.20) lucid; urgency=low

  [ Andy Whitcroft ]

  * rebuild following the GCC update to match compiler for out of tree modules
  * Revert "[Config] drbd -- enable"
  * Revert "ubuntu: drbd -- version 8.3.1"
  * SAUCE: khubd -- switch USB product/manufacturer/serial handling to RCU
    - LP: #510937
 -- Andy Whitcroft <email address hidden> Fri, 19 Feb 2010 18:47:18 +0000

Changed in linux (Ubuntu Lucid):
status: Confirmed → Fix Released
Andy Whitcroft (apw) on 2010-03-02
Changed in udev (Ubuntu Lucid):
status: Won't Fix → Invalid
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Related blueprints