Message-Id: <200806102206.26818.chris2553@googlemail.com>
Date:	Tue, 10 Jun 2008 22:06:26 +0000
From:	Chris Clayton <chris2553@...glemail.com>
To:	James Bottomley <James.Bottomley@...senpartnership.com>
Cc:	Andrew Morton <akpm@...ux-foundation.org>,
	LKML <linux-kernel@...r.kernel.org>, linux-scsi@...r.kernel.org,
	Hannes Reinecke <hare@...e.de>,
	"Rafael J. Wysocki" <rjw@...k.pl>, linux-usb@...r.kernel.org,
	Stefan Richter <stefanr@...6.in-berlin.de>
Subject: Re: 2,6.26-rc4-git2 - long pause during boot


[Apologies to copy recipients - I accidentally replied to only James earlier 
this evening. I've enclosed the text of my reply in square brackets at the 
relevant places below, followed, where appropriate, by my findings from 
tonight's investigations]

On Sunday 08 June 2008, James Bottomley wrote:
> On Sun, 2008-06-08 at 06:19 +0000, Chris Clayton wrote:
> > --Boundary-00=_NG3SIU63+Zdv2JV
> > Content-Type: text/plain;
> >   charset="utf-8"
> > Content-Transfer-Encoding: quoted-printable
> > Content-Disposition: inline
> >
> > On Friday 06 June 2008, James Bottomley wrote:
> > > On Fri, 2008-06-06 at 11:03 -0700, Andrew Morton wrote:
> > > > On Fri, 06 Jun 2008 10:22:22 -0500 James Bottomley=20
> >
> > <James.Bottomley@...senPartnership.com> wrote:
> > > > > On Thu, 2008-06-05 at 23:25 -0700, Andrew Morton wrote:
> > > > > > On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton=20
> >
> > <akpm@...ux-foundation.org> wrote:
> > > > > > > <watches wodim wibble for five minutes then report
> > > > > > > "CD/DVD-Record=
> >
> > er
> >
> > > > > > > not ready."  Pretends not to have noticed.>
> > > > > >
> > > > > > It goes much better when the CD is inserted upside up.
> > > > >
> > > > > So I can close this regression if I send you a pack of CD ring
> > > > > labels with "other way up" on them for you to affix to the
> > > > > underside of your CDs ... ?
> > > >
> > > > Would prefer double-sided CDs.
> > >
> > > I just discovered my budget only runs to a permanent marker for you to
> > > write the instructions on the rim yourself ...
> > >
> > > > Is this 20-second-delay thing known-about/expected/etc?
> > >
> > > If it's not the scsi_bus_uevent problem, then no, it isn't.
> > >
> > > The odd thing is that it occurs in the middle of USB initialisation
> > > from
> >
> > Because of this oddity, I've also built 2.6.26-rc5-git2 with verbose USB
> > debugging on. A boot log from that kernel is attached. You will see lots
> > of ETIME errors from usb. A log from a similarly verbose 2.6.25.5 kernel
> > does not show these errors. usb-devel added to cc list.
>
> I'm starting to think this might be a distribution problem.  I tried
> booting my laptop on your config (only system I have with ata_piix)
> without an initrd (bit painful for fedora 9) and I didn't see any slow
> downs (in fact it was a lot faster than previously; makes note to file
> bug with redhat about their initramfs).
>
 [OK, I'll start investigating this line. My desktop system was originally (the 
 now lapsed) Peanut Linux, which was a Slackware derivative. But I've been 
 running it for 3 or 4 years, upgrading and adding packages along the way. My 
 udev setup is based on that in a fairly recent Slackware, although I can't now 
 recall precisely which version.]

For the time being I'll try and isolate what it is that causes the delay in 
icons appearing on my desktop when I plug in a usb-storage device. The script 
that shows the icon is invoked by adding the script name to udev's run list. 
Here is a typical rule from /etc/udev/rules.d/20-local.rules:

ACTION=="add", KERNEL=="sd[a-z][0-9]", SYSFS{idProduct}=="6545", 
SYSFS{idVendor}=="0930", SYMLINK+="usbstickc%n", MODE="0666", 
RUN+="/usr/bin/udevshowicon.sh"

I've added a couple of calls to logger (from util-linux-2.12r) to the script. 
What this has shown is that, when I plug in a usb-storage device, there seems 
to be a delay between the usb/scsi/usb-storage drivers setting up the device 
and my icon-showing script being run. Here is the snippet from the kernel log 
file:

Jun 10 20:27:45 upstairs kernel: [ 3200.592107] hub 3-0:1.0: state 7 ports 5 chg 
0000 evt 0004
Jun 10 20:27:45 upstairs kernel: [ 3200.592107] ehci_hcd 0000:02:0a.2: GetStatus 
port 2 status 001803 POWER sig=j CSC CONNECT
Jun 10 20:27:45 upstairs kernel: [ 3200.592107] hub 3-0:1.0: port 2, status 
0501, change 0001, 480 Mb/s
Jun 10 20:27:45 upstairs kernel: [ 3200.695130] hub 3-0:1.0: debounce: port 2: 
total 100ms stable 100ms status 0x501
Jun 10 20:27:45 upstairs kernel: [ 3200.746270] ehci_hcd 0000:02:0a.2: port 2 
high speed
Jun 10 20:27:45 upstairs kernel: [ 3200.746279] ehci_hcd 0000:02:0a.2: GetStatus 
port 2 status 001005 POWER sig=se0 PE CONNECT
Jun 10 20:27:45 upstairs kernel: [ 3200.797136] usb 3-2: new high speed USB 
device using ehci_hcd and address 9
Jun 10 20:27:45 upstairs kernel: [ 3200.811464] usb 3-2: default language 0x0409
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] device: '3-2': device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] bus: 'usb': add device 3-2
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] PM: Adding info for usb:3-2
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] usb 3-2: uevent
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] bus: 'usb': driver_probe_device: 
matched device 3-2 with driver usb
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] bus: 'usb': really_probe: 
probing driver usb with device 3-2
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] usb 3-2: usb_probe_device
Jun 10 20:27:45 upstairs kernel: [ 3200.812116] usb 3-2: configuration #1 chosen 
from 1 choice
Jun 10 20:27:45 upstairs kernel: [ 3200.814424] usb 3-2: adding 3-2:1.0 (config 
#1, interface 0)
Jun 10 20:27:45 upstairs kernel: [ 3200.814434] device: '3-2:1.0': device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.814458] bus: 'usb': add device 3-2:1.0
Jun 10 20:27:45 upstairs kernel: [ 3200.814466] PM: Adding info for usb:3-2:1.0
Jun 10 20:27:45 upstairs kernel: [ 3200.814479] usb 3-2:1.0: uevent
Jun 10 20:27:45 upstairs kernel: [ 3200.814520] bus: 'usb': driver_probe_device: 
matched device 3-2:1.0 with driver usb-storage
Jun 10 20:27:45 upstairs kernel: [ 3200.814526] bus: 'usb': really_probe: 
probing driver usb-storage with device 3-2:1.0
Jun 10 20:27:45 upstairs kernel: [ 3200.814569] usb-storage 3-2:1.0: 
usb_probe_interface
Jun 10 20:27:45 upstairs kernel: [ 3200.814577] usb-storage 3-2:1.0: 
usb_probe_interface - got id
Jun 10 20:27:45 upstairs kernel: [ 3200.814982] scsi10 : SCSI emulation for USB 
Mass Storage devices
Jun 10 20:27:45 upstairs kernel: [ 3200.814994] device: 'host10': device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.815006] bus: 'scsi': add device host10
Jun 10 20:27:45 upstairs kernel: [ 3200.815020] PM: Adding info for scsi:host10
Jun 10 20:27:45 upstairs kernel: [ 3200.815051] device: 'host10': device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.815143] PM: Adding info for No 
Bus:host10
Jun 10 20:27:45 upstairs kernel: [ 3200.815303] driver: '3-2:1.0': driver_bound: 
bound to device 'usb-storage'
Jun 10 20:27:45 upstairs kernel: [ 3200.815310] bus: 'usb': really_probe: bound 
device 3-2:1.0 to driver usb-storage
Jun 10 20:27:45 upstairs kernel: [ 3200.815325] device: 'usbdev3.9_ep81': 
device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.815375] PM: Adding info for No 
Bus:usbdev3.9_ep81
Jun 10 20:27:45 upstairs kernel: [ 3200.815401] device: 'usbdev3.9_ep02': 
device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.815421] PM: Adding info for No 
Bus:usbdev3.9_ep02
Jun 10 20:27:45 upstairs kernel: [ 3200.815437] drivers/usb/core/inode.c: 
creating file '009'
Jun 10 20:27:45 upstairs kernel: [ 3200.815446] driver: '3-2': driver_bound: 
bound to device 'usb'
Jun 10 20:27:45 upstairs kernel: [ 3200.815449] bus: 'usb': really_probe: bound 
device 3-2 to driver usb
Jun 10 20:27:45 upstairs kernel: [ 3200.815459] device: 'usbdev3.9_ep00': 
device_add
Jun 10 20:27:45 upstairs kernel: [ 3200.815478] PM: Adding info for No 
Bus:usbdev3.9_ep00
Jun 10 20:27:45 upstairs kernel: [ 3200.815492] usb 3-2: New USB device found, 
idVendor=0930, idProduct=6545
Jun 10 20:27:45 upstairs kernel: [ 3200.815495] usb 3-2: New USB device strings: 
Mfr=0, Product=2, SerialNumber=3
Jun 10 20:27:45 upstairs kernel: [ 3200.815497] usb 3-2: Product: USB Flash 
Memory
Jun 10 20:27:45 upstairs kernel: [ 3200.815500] usb 3-2: SerialNumber: 
0EC065712361A91E
Jun 10 20:27:45 upstairs kernel: [ 3200.815769] usb-storage: device found at 9
Jun 10 20:27:45 upstairs kernel: [ 3200.815772] usb-storage: waiting for device 
to settle before scanning
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] scsi 10:0:0:0: Direct-Access              
USB Flash Memory 5.00 PQ: 0 ANSI: 0 CCS
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] device: 'target10:0:0': 
device_add
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': add device 
target10:0:0
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] PM: Adding info for 
scsi:target10:0:0
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] device: '10:0:0:0': device_add
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': add device 10:0:0:0
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] PM: Adding info for 
scsi:10:0:0:0
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': 
driver_probe_device: matched device 10:0:0:0 with driver sd
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] bus: 'scsi': really_probe: 
probing driver sd with device 10:0:0:0
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] device: '10:0:0:0': device_add
Jun 10 20:27:50 upstairs kernel: [ 3205.817115] PM: Adding info for No 
Bus:10:0:0:0
Jun 10 20:27:51 upstairs kernel: [ 3206.045117] sd 10:0:0:0: [sdd] 2013184 
512-byte hardware sectors (1031 MB)
Jun 10 20:27:51 upstairs kernel: [ 3206.045369] sd 10:0:0:0: [sdd] Write Protect 
is off
Jun 10 20:27:51 upstairs kernel: [ 3206.045380] sd 10:0:0:0: [sdd] Mode Sense: 
23 00 00 00
Jun 10 20:27:51 upstairs kernel: [ 3206.045386] sd 10:0:0:0: [sdd] Assuming 
drive cache: write through
Jun 10 20:27:51 upstairs kernel: [ 3206.045425] device: 'sdd': device_add
Jun 10 20:27:51 upstairs kernel: [ 3206.045495] PM: Adding info for No Bus:sdd
Jun 10 20:27:51 upstairs kernel: [ 3206.047204] sd 10:0:0:0: [sdd] 2013184 
512-byte hardware sectors (1031 MB)
Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sd 10:0:0:0: [sdd] Write Protect 
is off
Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sd 10:0:0:0: [sdd] Mode Sense: 
23 00 00 00
Jun 10 20:27:51 upstairs kernel: [ 3206.047306] sd 10:0:0:0: [sdd] Assuming 
drive cache: write through
Jun 10 20:27:51 upstairs kernel: [ 3206.047306]  sdd: sdd1
Jun 10 20:27:51 upstairs kernel: [ 3206.049452] device: 'sdd1': device_add
Jun 10 20:27:51 upstairs kernel: [ 3206.049482] PM: Adding info for No Bus:sdd1
Jun 10 20:27:51 upstairs kernel: [ 3206.049594] device: '8:48': device_add
Jun 10 20:27:51 upstairs kernel: [ 3206.049623] PM: Adding info for No Bus:8:48
Jun 10 20:27:51 upstairs kernel: [ 3206.049648] sd 10:0:0:0: [sdd] Attached SCSI 
removable disk
Jun 10 20:27:51 upstairs kernel: [ 3206.049654] driver: '10:0:0:0': 
driver_bound: bound to device 'sd'
Jun 10 20:27:51 upstairs kernel: [ 3206.049660] bus: 'scsi': really_probe: bound 
device 10:0:0:0 to driver sd
Jun 10 20:27:51 upstairs kernel: [ 3206.049667] device: '10:0:0:0': device_add
Jun 10 20:27:51 upstairs kernel: [ 3206.049691] PM: Adding info for No 
Bus:10:0:0:0
Jun 10 20:27:51 upstairs kernel: [ 3206.050108] usb-storage: device scan 
complete

And here is the output from the calls to logger, that get written 
to /var/log/messages:

Jun 10 20:28:07 upstairs logger: udevshowicon: starting to get icon name
Jun 10 20:28:07 upstairs logger: udevshowicon: about to show usbstickc1

As you can see, 16 seconds elapses between the drivers finishing and the script 
being run. That's an awful time on a system that is doing nothing (because I'm 
busy scratching my head and looking bewildered :-)

I'm using udev-121, which is pretty recent. There is a later version, but the 
changelog doesn't describe any fixes that (to me) sound as if they would come 
anywhere near this problem.

I'll do so more poking about tomorrow night, but if anyone has any ideas in the 
meantime, I'd be very grateful.

> The one thing the patch you identified does is to add the SCSI target to
> the BUS and type model for the generic device.  What this does is to add
> extra uevents for the target.  If your hotplug handlers aren't set up to
> expect this, they could be delaying the system progress.
>
> What hotplug scripts are you using (and does /sbin/hotplug exist)?
>

 [ I don't have hotplug installed and CONFIG_UEVENT_HELPER_PATH is set to
 the empty string.]

> > > > upstairs kernel: usb 11-2: Product: USB Flash Memory Jun  6 17:26:31
> > > > upstairs kernel: usb 11-2: SerialNumber: 0EC065712361A91E
> > >
> > > I'm a bit baffled as to how that could be SCSI related, but I suppose
> > > it could be udev related somehow.  Perhaps turning on driver core
> > > debugging might help (that's CONFIG_DEBUG DRIVER ... it depends on
> > > CONFIG_DEBUG_KERNEL for activation).  Hopefully the verbose kernel logs
> > > from here might tell us what's going on in the lacunae.
> >
> > Triggered by James' bafflement and for my own peace of mind, I've run
> > another bisect session. This time I started with v2.6.26 as good and
> > v2.6.26-rc2 as bad. It highlighted the same patch as the "culprit".
>
> Actually, that's not really necessary.  Bisection is taking you back
> through kernel history, so unless the bug has two separate causes, it's
> pretty likely to home in on the same section of code.
>

 [I appreciate that but I was a tint bit worried that, late i the process, I had 
 reported an erronious good or bad to git bisect and ended up in the wrong 
 place.]

> James

I've also attached a log from a boot with CONFIG_PRINTK_TIME enabled.

Thanks

Chris

-- 
Beauty is in the eye of the beerholder.

View attachment "printktimer.log" of type "text/x-log" (53452 bytes)

Powered by blists - more mailing lists