linux-kernel - Re: 2,6.26-rc4-git2 - long pause during boot

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <200806080619.17531.chris2553@googlemail.com>
Date:	Sun, 8 Jun 2008 06:19:17 +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
Subject: Re: 2,6.26-rc4-git2 - long pause during boot

--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.


> the log:
> > =EF=BB=BFJun  6 17:25:19 upstairs kernel: uhci_hcd 0000:00:1d.0: UHCI H=
ost
> > Controller Jun  6 17:25:19 upstairs kernel: uhci_hcd 0000:00:1d.0: new
> > USB bus registered, assigned bus number 1 Jun  6 17:25:19 upstairs
> > kernel: uhci_hcd 0000:00:1d.0: irq 16, io base 0x0000a800 Jun  6 17:25:=
19
> > upstairs kernel: usb usb1: configuration #1 chosen from 1 choice Jun  6
> > 17:25:19 upstairs kernel: hub 1-0:1.0: USB hub found
> > Jun  6 17:25:19 upstairs kernel: hub 1-0:1.0: 2 ports detected
> > Jun  6 17:25:44 upstairs kernel: ohci_hcd: 2006 August 04 USB 1.1 'Open'
> > Host Controller (OHCI) Driver Jun  6 17:25:44 upstairs kernel: usb usb1:
> > New USB device found, idVendor=3D1d6b, idProduct=3D0001 Jun  6 17:25:44
> > upstairs kernel: usb usb1: New USB device strings: Mfr=3D3, Product=3D2,
> > SerialNumber=3D1 Jun  6 17:25:44 upstairs kernel: usb usb1: Product: UH=
CI
> > Host Controller Jun  6 17:25:44 upstairs kernel: usb usb1: Manufacturer:
> > Linux 2.6.26-rc5 uhci_hcd
>
> Note the jump from 19 to 44 seconds.
>
> There's another one here:
> > =EF=BB=BFJun  6 17:25:44 upstairs kernel: EXT3-fs: mounted filesystem w=
ith
> > ordered data mode. Jun  6 17:25:44 upstairs kernel: Adding 4096532k swap
> > on /dev/sda5.  Priority:-1 extents:1 across:4096532k Jun  6 17:25:44
> > upstairs kernel: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1 Jun  6
> > 17:25:44 upstairs kernel: ip_tables: (C) 2000-2006 Netfilter Core Team
> > Jun  6 17:25:44 upstairs kernel: nf_conntrack version 0.5.0 (16384
> > buckets, 65536 max) Jun  6 17:25:44 upstairs kernel: parport_pc 00:06:
> > disabled
> > Jun  6 17:25:44 upstairs kernel: pnp: the driver 'parport_pc' has been
> > unregistered Jun  6 17:25:44 upstairs kernel: ieee1394: Node removed:
> > ID:BUS[0-00:1023]  GUID[00110666000013cc] Jun  6 17:26:31 upstairs
> > kernel: usb 11-2: new high speed USB device using ehci_hcd and address 3
> > Jun  6 17:26:31 upstairs kernel: usb 11-2: configuration #1 chosen from=
 1
> > choice Jun  6 17:26:31 upstairs kernel: usb 11-2: New USB device found,
> > idVendor=3D0930, idProduct=3D6545 Jun  6 17:26:31 upstairs kernel: usb =
11-2:
> > New USB device strings: Mfr=3D0, Product=3D2, SerialNumber=3D3 Jun  6 1=
7:26:31
> > 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".


Chris
> James

--
Beauty is in the eye of the beerholder.


View attachment "driver+usbdebug.log" of type "text/x-log" (57322 bytes)