Hi,
I've just started testing 2.6.26 on my desktop machine and have found that I get
a long pause (20 seconds or so) as the system boots. By pause I mean that the
boot messages that normally scroll by stop doing so for, as I say, about 20
seconds.
I've done a bisect and arrived at:
b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
commit b0ed43360fdca227048d88a08290365cb681c1a8
Author: Hannes Reinecke <[email protected]>
Date: Tue Mar 18 14:32:28 2008 +0100
[SCSI] add scsi_host and scsi_target to scsi_bus
This patch implements scsi_host and scsi_target device types
and adds both to the scsi_bus.
Signed-off-by: Hannes Reinecke <[email protected]>
Signed-off-by: Kay Sievers <[email protected]>
Signed-off-by: James Bottomley <[email protected]>
:040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
The config file for that kernel is attached as are the kernel log for booting
that kernel and the bisect log.
I've also noticed that it takes much longer for icons to appear on my desktop
when I plug a usb storage device in. (The icons are shown/hidden by a simple
sctript that is run via udev when the device is attached/detached.)
Let me know of any way I can help solve this.
Please cc me to any reply as I'm not subscribed.
Chris
--
Beauty is in the eye of the beerholder.
On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton <[email protected]> wrote:
> Hi,
>
> I've just started testing 2.6.26 on my desktop machine and have found that I get
> a long pause (20 seconds or so) as the system boots. By pause I mean that the
> boot messages that normally scroll by stop doing so for, as I say, about 20
> seconds.
>
> I've done a bisect and arrived at:
>
> b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> commit b0ed43360fdca227048d88a08290365cb681c1a8
> Author: Hannes Reinecke <[email protected]>
> Date: Tue Mar 18 14:32:28 2008 +0100
>
> [SCSI] add scsi_host and scsi_target to scsi_bus
>
> This patch implements scsi_host and scsi_target device types
> and adds both to the scsi_bus.
>
> Signed-off-by: Hannes Reinecke <[email protected]>
> Signed-off-by: Kay Sievers <[email protected]>
> Signed-off-by: James Bottomley <[email protected]>
>
> :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
>
> The config file for that kernel is attached as are the kernel log for booting
> that kernel and the bisect log.
>
> I've also noticed that it takes much longer for icons to appear on my desktop
> when I plug a usb storage device in. (The icons are shown/hidden by a simple
> sctript that is run via udev when the device is attached/detached.)
Do you believe that this is the same period? 20 seconds?
> Let me know of any way I can help solve this.
>
> Please cc me to any reply as I'm not subscribed.
cc's added.
Rafael, we might need to track this as a post-2.6.26 regression.
On Friday 06 June 2008, Andrew Morton wrote:
> On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton <[email protected]>
wrote:
> > Hi,
> >
> > I've just started testing 2.6.26 on my desktop machine and have found
> > that I get a long pause (20 seconds or so) as the system boots. By pause
> > I mean that the boot messages that normally scroll by stop doing so for,
> > as I say, about 20 seconds.
> >
> > I've done a bisect and arrived at:
> >
> > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > Author: Hannes Reinecke <[email protected]>
> > Date: Tue Mar 18 14:32:28 2008 +0100
> >
> > [SCSI] add scsi_host and scsi_target to scsi_bus
> >
> > This patch implements scsi_host and scsi_target device types
> > and adds both to the scsi_bus.
> >
> > Signed-off-by: Hannes Reinecke <[email protected]>
> > Signed-off-by: Kay Sievers <[email protected]>
> > Signed-off-by: James Bottomley
> > <[email protected]>
> >
> > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> >
> > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> >
> > The config file for that kernel is attached as are the kernel log for
> > booting that kernel and the bisect log.
> >
> > I've also noticed that it takes much longer for icons to appear on my
> > desktop when I plug a usb storage device in. (The icons are shown/hidden
> > by a simple sctript that is run via udev when the device is
> > attached/detached.)
>
> Do you believe that this is the same period? 20 seconds?
>
Thanks for the reply, Andrew. I was beginning to think that I'd committed an
LKML sin :-)
Yes, it is about the same. On 2.6.25.4 (and earlier), the icons appear within a
second or two, but with 2.6.26-rc2 or later, it takes about 20 seconds. I've
now built and installed -rc5 and am seeing the same behaviour.
I've also built -rc5 on my laptop. On that my kernel uses the older IDE drivers
rather than libata. The boot proceeds with no pause, but I do see the same
delay in the desktop icons appearing when I attach a usb-storage device.
> > Let me know of any way I can help solve this.
> >
> > Please cc me to any reply as I'm not subscribed.
>
> cc's added.
>
> Rafael, we might need to track this as a post-2.6.26 regression.
--
Beauty is in the eye of the beerholder.
On Fri, 6 Jun 2008 06:07:29 +0000 Chris Clayton <[email protected]> wrote:
> On Friday 06 June 2008, Andrew Morton wrote:
> > On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton <[email protected]>
> wrote:
> > > Hi,
> > >
> > > I've just started testing 2.6.26 on my desktop machine and have found
> > > that I get a long pause (20 seconds or so) as the system boots. By pause
> > > I mean that the boot messages that normally scroll by stop doing so for,
> > > as I say, about 20 seconds.
> > >
> > > I've done a bisect and arrived at:
> > >
> > > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > > Author: Hannes Reinecke <[email protected]>
> > > Date: Tue Mar 18 14:32:28 2008 +0100
> > >
> > > [SCSI] add scsi_host and scsi_target to scsi_bus
> > >
> > > This patch implements scsi_host and scsi_target device types
> > > and adds both to the scsi_bus.
> > >
> > > Signed-off-by: Hannes Reinecke <[email protected]>
> > > Signed-off-by: Kay Sievers <[email protected]>
> > > Signed-off-by: James Bottomley
> > > <[email protected]>
> > >
> > > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> > >
> > > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> > >
> > > The config file for that kernel is attached as are the kernel log for
> > > booting that kernel and the bisect log.
> > >
> > > I've also noticed that it takes much longer for icons to appear on my
> > > desktop when I plug a usb storage device in. (The icons are shown/hidden
> > > by a simple sctript that is run via udev when the device is
> > > attached/detached.)
> >
> > Do you believe that this is the same period? 20 seconds?
> >
>
> Thanks for the reply, Andrew. I was beginning to think that I'd committed an
> LKML sin :-)
Well you did - you reported a bug.
<watches wodim wibble for five minutes then report "CD/DVD-Recorder
not ready." Pretends not to have noticed.>
> Yes, it is about the same. On 2.6.25.4 (and earlier), the icons appear within a
> second or two, but with 2.6.26-rc2 or later, it takes about 20 seconds. I've
> now built and installed -rc5 and am seeing the same behaviour.
>
> I've also built -rc5 on my laptop. On that my kernel uses the older IDE drivers
> rather than libata. The boot proceeds with no pause, but I do see the same
> delay in the desktop icons appearing when I attach a usb-storage device.
OK that makes sense. ata and usb use the scsi layer. IDE does not.
On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton <[email protected]> wrote:
> <watches wodim wibble for five minutes then report "CD/DVD-Recorder
> not ready." Pretends not to have noticed.>
It goes much better when the CD is inserted upside up.
On Friday, 6 of June 2008, Andrew Morton wrote:
> On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton <[email protected]> wrote:
>
> > Hi,
> >
> > I've just started testing 2.6.26 on my desktop machine and have found that I get
> > a long pause (20 seconds or so) as the system boots. By pause I mean that the
> > boot messages that normally scroll by stop doing so for, as I say, about 20
> > seconds.
> >
> > I've done a bisect and arrived at:
> >
> > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > Author: Hannes Reinecke <[email protected]>
> > Date: Tue Mar 18 14:32:28 2008 +0100
> >
> > [SCSI] add scsi_host and scsi_target to scsi_bus
> >
> > This patch implements scsi_host and scsi_target device types
> > and adds both to the scsi_bus.
> >
> > Signed-off-by: Hannes Reinecke <[email protected]>
> > Signed-off-by: Kay Sievers <[email protected]>
> > Signed-off-by: James Bottomley <[email protected]>
> >
> > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> >
> > The config file for that kernel is attached as are the kernel log for booting
> > that kernel and the bisect log.
> >
> > I've also noticed that it takes much longer for icons to appear on my desktop
> > when I plug a usb storage device in. (The icons are shown/hidden by a simple
> > sctript that is run via udev when the device is attached/detached.)
>
> Do you believe that this is the same period? 20 seconds?
>
> > Let me know of any way I can help solve this.
> >
> > Please cc me to any reply as I'm not subscribed.
>
> cc's added.
>
> Rafael, we might need to track this as a post-2.6.26 regression.
We're tracking it as http://bugzilla.kernel.org/show_bug.cgi?id=10861 .
Thanks,
Rafael
On Fri, 2008-06-06 at 06:07 +0000, Chris Clayton wrote:
> On Friday 06 June 2008, Andrew Morton wrote:
> > On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton <[email protected]>
> wrote:
> > > Hi,
> > >
> > > I've just started testing 2.6.26 on my desktop machine and have found
> > > that I get a long pause (20 seconds or so) as the system boots. By pause
> > > I mean that the boot messages that normally scroll by stop doing so for,
> > > as I say, about 20 seconds.
> > >
> > > I've done a bisect and arrived at:
> > >
> > > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > > Author: Hannes Reinecke <[email protected]>
> > > Date: Tue Mar 18 14:32:28 2008 +0100
> > >
> > > [SCSI] add scsi_host and scsi_target to scsi_bus
> > >
> > > This patch implements scsi_host and scsi_target device types
> > > and adds both to the scsi_bus.
> > >
> > > Signed-off-by: Hannes Reinecke <[email protected]>
> > > Signed-off-by: Kay Sievers <[email protected]>
> > > Signed-off-by: James Bottomley
> > > <[email protected]>
> > >
> > > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> > >
> > > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> > >
> > > The config file for that kernel is attached as are the kernel log for
> > > booting that kernel and the bisect log.
> > >
> > > I've also noticed that it takes much longer for icons to appear on my
> > > desktop when I plug a usb storage device in. (The icons are shown/hidden
> > > by a simple sctript that is run via udev when the device is
> > > attached/detached.)
> >
> > Do you believe that this is the same period? 20 seconds?
> >
>
> Thanks for the reply, Andrew. I was beginning to think that I'd committed an
> LKML sin :-)
>
> Yes, it is about the same. On 2.6.25.4 (and earlier), the icons appear within a
> second or two, but with 2.6.26-rc2 or later, it takes about 20 seconds. I've
> now built and installed -rc5 and am seeing the same behaviour.
>
> I've also built -rc5 on my laptop. On that my kernel uses the older IDE drivers
> rather than libata. The boot proceeds with no pause, but I do see the same
> delay in the desktop icons appearing when I attach a usb-storage device.
>
> > > Let me know of any way I can help solve this.
> > >
> > > Please cc me to any reply as I'm not subscribed.
> >
> > cc's added.
> >
> > Rafael, we might need to track this as a post-2.6.26 regression.
It already is ... as I asked in the actual bug (but no-one seems to have
noticed, so I assume the bug entry isn't set up correctly). Does this
still persist with 2.6.26-rc5? The reason for asking is that it looks
very much like a silent manifestation of our scsi_bus_uevent() problem
that got fixed in 2.6.26-rc5.
James
On Friday, 6 of June 2008, James Bottomley wrote:
> On Fri, 2008-06-06 at 06:07 +0000, Chris Clayton wrote:
> > On Friday 06 June 2008, Andrew Morton wrote:
> > > On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton <[email protected]>
> > wrote:
> > > > Hi,
> > > >
> > > > I've just started testing 2.6.26 on my desktop machine and have found
> > > > that I get a long pause (20 seconds or so) as the system boots. By pause
> > > > I mean that the boot messages that normally scroll by stop doing so for,
> > > > as I say, about 20 seconds.
> > > >
> > > > I've done a bisect and arrived at:
> > > >
> > > > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > > > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > > > Author: Hannes Reinecke <[email protected]>
> > > > Date: Tue Mar 18 14:32:28 2008 +0100
> > > >
> > > > [SCSI] add scsi_host and scsi_target to scsi_bus
> > > >
> > > > This patch implements scsi_host and scsi_target device types
> > > > and adds both to the scsi_bus.
> > > >
> > > > Signed-off-by: Hannes Reinecke <[email protected]>
> > > > Signed-off-by: Kay Sievers <[email protected]>
> > > > Signed-off-by: James Bottomley
> > > > <[email protected]>
> > > >
> > > > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> > > >
> > > > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> > > >
> > > > The config file for that kernel is attached as are the kernel log for
> > > > booting that kernel and the bisect log.
> > > >
> > > > I've also noticed that it takes much longer for icons to appear on my
> > > > desktop when I plug a usb storage device in. (The icons are shown/hidden
> > > > by a simple sctript that is run via udev when the device is
> > > > attached/detached.)
> > >
> > > Do you believe that this is the same period? 20 seconds?
> > >
> >
> > Thanks for the reply, Andrew. I was beginning to think that I'd committed an
> > LKML sin :-)
> >
> > Yes, it is about the same. On 2.6.25.4 (and earlier), the icons appear within a
> > second or two, but with 2.6.26-rc2 or later, it takes about 20 seconds. I've
> > now built and installed -rc5 and am seeing the same behaviour.
> >
> > I've also built -rc5 on my laptop. On that my kernel uses the older IDE drivers
> > rather than libata. The boot proceeds with no pause, but I do see the same
> > delay in the desktop icons appearing when I attach a usb-storage device.
> >
> > > > Let me know of any way I can help solve this.
> > > >
> > > > Please cc me to any reply as I'm not subscribed.
> > >
> > > cc's added.
> > >
> > > Rafael, we might need to track this as a post-2.6.26 regression.
>
> It already is ... as I asked in the actual bug (but no-one seems to have
> noticed, so I assume the bug entry isn't set up correctly).
The bug reporter has no Bugzilla account, so I couldn't add him to the CC list
of the bug.
Thanks,
Rafael
On Thu, 2008-06-05 at 23:25 -0700, Andrew Morton wrote:
> On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton <[email protected]> wrote:
>
> > <watches wodim wibble for five minutes then report "CD/DVD-Recorder
> > 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 ... ?
James
On Friday 06 June 2008, James Bottomley wrote:
> On Fri, 2008-06-06 at 06:07 +0000, Chris Clayton wrote:
> > On Friday 06 June 2008, Andrew Morton wrote:
> > > On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton
> > > <[email protected]>
> >
> > wrote:
> > > > Hi,
> > > >
> > > > I've just started testing 2.6.26 on my desktop machine and have found
> > > > that I get a long pause (20 seconds or so) as the system boots. By
> > > > pause I mean that the boot messages that normally scroll by stop
> > > > doing so for, as I say, about 20 seconds.
> > > >
> > > > I've done a bisect and arrived at:
> > > >
> > > > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > > > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > > > Author: Hannes Reinecke <[email protected]>
> > > > Date: Tue Mar 18 14:32:28 2008 +0100
> > > >
> > > > [SCSI] add scsi_host and scsi_target to scsi_bus
> > > >
> > > > This patch implements scsi_host and scsi_target device types
> > > > and adds both to the scsi_bus.
> > > >
> > > > Signed-off-by: Hannes Reinecke <[email protected]>
> > > > Signed-off-by: Kay Sievers <[email protected]>
> > > > Signed-off-by: James Bottomley
> > > > <[email protected]>
> > > >
> > > > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> > > >
> > > > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> > > >
> > > > The config file for that kernel is attached as are the kernel log for
> > > > booting that kernel and the bisect log.
> > > >
> > > > I've also noticed that it takes much longer for icons to appear on my
> > > > desktop when I plug a usb storage device in. (The icons are
> > > > shown/hidden by a simple sctript that is run via udev when the device
> > > > is
> > > > attached/detached.)
> > >
> > > Do you believe that this is the same period? 20 seconds?
> >
> > Thanks for the reply, Andrew. I was beginning to think that I'd committed
> > an LKML sin :-)
> >
> > Yes, it is about the same. On 2.6.25.4 (and earlier), the icons appear
> > within a second or two, but with 2.6.26-rc2 or later, it takes about 20
> > seconds. I've now built and installed -rc5 and am seeing the same
> > behaviour.
> >
> > I've also built -rc5 on my laptop. On that my kernel uses the older IDE
> > drivers rather than libata. The boot proceeds with no pause, but I do see
> > the same delay in the desktop icons appearing when I attach a usb-storage
> > device.
> >
> > > > Let me know of any way I can help solve this.
> > > >
> > > > Please cc me to any reply as I'm not subscribed.
> > >
> > > cc's added.
> > >
> > > Rafael, we might need to track this as a post-2.6.26 regression.
>
> It already is ... as I asked in the actual bug (but no-one seems to have
> noticed, so I assume the bug entry isn't set up correctly). Does this
> still persist with 2.6.26-rc5? The reason for asking is that it looks
> very much like a silent manifestation of our scsi_bus_uevent() problem
> that got fixed in 2.6.26-rc5.
>
Yes, I still get the boot pause and the delay in desktop icons appearing when a
usb-storage device is plugged in with -rc5. A boot log is attached. Is there
some sort of verbose scsi boot messaging that I can switch on? I've looked but
I'm damned if I can find anything in 'make menuconfig'.
Chris
> James
--
Beauty is in the eye of the beerholder.
On Friday 06 June 2008, Rafael J. Wysocki wrote:
> On Friday, 6 of June 2008, James Bottomley wrote:
> > On Fri, 2008-06-06 at 06:07 +0000, Chris Clayton wrote:
> > > On Friday 06 June 2008, Andrew Morton wrote:
> > > > On Sun, 1 Jun 2008 04:15:05 +0000 Chris Clayton
> > > > <[email protected]>
> > >
> > > wrote:
> > > > > Hi,
> > > > >
> > > > > I've just started testing 2.6.26 on my desktop machine and have
> > > > > found that I get a long pause (20 seconds or so) as the system
> > > > > boots. By pause I mean that the boot messages that normally scroll
> > > > > by stop doing so for, as I say, about 20 seconds.
> > > > >
> > > > > I've done a bisect and arrived at:
> > > > >
> > > > > b0ed43360fdca227048d88a08290365cb681c1a8 is first bad commit
> > > > > commit b0ed43360fdca227048d88a08290365cb681c1a8
> > > > > Author: Hannes Reinecke <[email protected]>
> > > > > Date: Tue Mar 18 14:32:28 2008 +0100
> > > > >
> > > > > [SCSI] add scsi_host and scsi_target to scsi_bus
> > > > >
> > > > > This patch implements scsi_host and scsi_target device types
> > > > > and adds both to the scsi_bus.
> > > > >
> > > > > Signed-off-by: Hannes Reinecke <[email protected]>
> > > > > Signed-off-by: Kay Sievers <[email protected]>
> > > > > Signed-off-by: James Bottomley
> > > > > <[email protected]>
> > > > >
> > > > > :040000 040000 4e3140909966b4c9aa987d34ee4078d283fe0351
> > > > >
> > > > > 46e4fd28cc537ba700eb4f5652abf043fed4d76d M drivers
> > > > >
> > > > > The config file for that kernel is attached as are the kernel log
> > > > > for booting that kernel and the bisect log.
> > > > >
> > > > > I've also noticed that it takes much longer for icons to appear on
> > > > > my desktop when I plug a usb storage device in. (The icons are
> > > > > shown/hidden by a simple sctript that is run via udev when the
> > > > > device is attached/detached.)
> > > >
> > > > Do you believe that this is the same period? 20 seconds?
> > >
> > > Thanks for the reply, Andrew. I was beginning to think that I'd
> > > committed an LKML sin :-)
> > >
> > > Yes, it is about the same. On 2.6.25.4 (and earlier), the icons appear
> > > within a second or two, but with 2.6.26-rc2 or later, it takes about 20
> > > seconds. I've now built and installed -rc5 and am seeing the same
> > > behaviour.
> > >
> > > I've also built -rc5 on my laptop. On that my kernel uses the older IDE
> > > drivers rather than libata. The boot proceeds with no pause, but I do
> > > see the same delay in the desktop icons appearing when I attach a
> > > usb-storage device.
> > >
> > > > > Let me know of any way I can help solve this.
> > > > >
> > > > > Please cc me to any reply as I'm not subscribed.
> > > >
> > > > cc's added.
> > > >
> > > > Rafael, we might need to track this as a post-2.6.26 regression.
> >
> > It already is ... as I asked in the actual bug (but no-one seems to have
> > noticed, so I assume the bug entry isn't set up correctly).
>
> The bug reporter has no Bugzilla account, so I couldn't add him to the CC
> list of the bug.
>
I do have a bugzilla account, but for some reason I couldn't log in to it to
report this bug, so I mailed LKML to get the ball rolling. I can now log in so
I've added myself to the CC list.
Thanks.
> Thanks,
> Rafael
--
Beauty is in the eye of the beerholder.
On Fri, 06 Jun 2008 10:22:22 -0500 James Bottomley <[email protected]> wrote:
> On Thu, 2008-06-05 at 23:25 -0700, Andrew Morton wrote:
> > On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton <[email protected]> wrote:
> >
> > > <watches wodim wibble for five minutes then report "CD/DVD-Recorder
> > > 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.
Is this 20-second-delay thing known-about/expected/etc?
On Fri, 2008-06-06 at 11:03 -0700, Andrew Morton wrote:
> On Fri, 06 Jun 2008 10:22:22 -0500 James Bottomley <[email protected]> wrote:
>
> > On Thu, 2008-06-05 at 23:25 -0700, Andrew Morton wrote:
> > > On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton <[email protected]> wrote:
> > >
> > > > <watches wodim wibble for five minutes then report "CD/DVD-Recorder
> > > > 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
the log:
> Jun 6 17:25:19 upstairs kernel: uhci_hcd 0000:00:1d.0: UHCI Host 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=1d6b, idProduct=0001
> Jun 6 17:25:44 upstairs kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
> Jun 6 17:25:44 upstairs kernel: usb usb1: Product: UHCI 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:
> Jun 6 17:25:44 upstairs kernel: EXT3-fs: mounted filesystem with 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=0930, idProduct=6545
> Jun 6 17:26:31 upstairs kernel: usb 11-2: New USB device strings: Mfr=0, Product=2, SerialNumber=3
> Jun 6 17: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.
James
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
<[email protected]> wrote:
> > > On Thu, 2008-06-05 at 23:25 -0700, Andrew Morton wrote:
> > > > On Thu, 5 Jun 2008 23:21:45 -0700 Andrew Morton
<[email protected]> wrote:
> > > > > <watches wodim wibble for five minutes then report "CD/DVD-Recorder
> > > > > 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
>
> the log:
> > Jun 6 17:25:19 upstairs kernel: uhci_hcd 0000:00:1d.0: UHCI Host
> > 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=1d6b, idProduct=0001 Jun 6 17:25:44
> > upstairs kernel: usb usb1: New USB device strings: Mfr=3, Product=2,
> > SerialNumber=1 Jun 6 17:25:44 upstairs kernel: usb usb1: Product: UHCI
> > 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:
> > Jun 6 17:25:44 upstairs kernel: EXT3-fs: mounted filesystem with
> > 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=0930, idProduct=6545 Jun 6 17:26:31 upstairs kernel: usb 11-2:
> > New USB device strings: Mfr=0, Product=2, SerialNumber=3 Jun 6 17: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.
>
OK, here's a boot log with driver core debugging turned on. Hope it helps!
(Oh, and thanks for adding the word lacunae to my vocabulary. I'd never come
across it before.)
Chris
> James
--
Beauty is in the eye of the beerholder.
--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
<[email protected]> 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
<[email protected]> 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.
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
> <[email protected]> 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
> <[email protected]> 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).
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)?
> > > 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.
James
On Fri, Jun 6, 2008 at 10:35 AM, Chris Clayton <[email protected]> wrote:
>...
> Yes, I still get the boot pause and the delay in desktop icons appearing when a
> usb-storage device is plugged in with -rc5. A boot log is attached. Is there
> some sort of verbose scsi boot messaging that I can switch on? I've looked but
> I'm damned if I can find anything in 'make menuconfig'.
SCSI_CONSTANTS and SCSI_LOGGING might help.
Both live in the SCSI options menu. Read the Kconfig help on how
to use SCSI_LOGGING.
Can you please also enable CONFIG_PRINTK_TIME ?
Using the timestamps in /var/log/messages is ok but not the most
reliable place to get somewhat accurate time stamps of events.
hth,
grant
On Sun, 8 Jun 2008, Chris Clayton wrote:
> > 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.
In fact the log shows that the 30-second delay occurs in the middle of
ohci1394 (Firewire) initialization, not USB initialization:
Jun 8 05:26:35 upstairs kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[22] MMIO=[fbfff000-fbfff7ff] Max Packet=[2048] IR/IT contexts=[4/8]
Jun 8 05:26:35 upstairs kernel: ohci_hcd 0000:02:0a.0: urb f71cb680 path 2 ep1in 5e160000 cc 5 --> status -62
Jun 8 05:26:35 upstairs kernel: hub 1-2:1.0: transfer --> -62
Jun 8 05:27:08 upstairs kernel: driver: '0000:02:0b.0': driver_bound: bound to device 'ohci1394'
Jun 8 05:27:08 upstairs kernel: bus: 'pci': really_probe: bound device 0000:02:0b.0 to driver ohci1394
Those -62 errors from ohci_hcd are red herrings. To test this, try
booting with "nousb".
Alan Stern
Alan Stern wrote:
> In fact the log shows that the 30-second delay occurs in the middle of
> ohci1394 (Firewire) initialization, not USB initialization:
>
> Jun 8 05:26:35 upstairs kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI): IRQ=[22] MMIO=[fbfff000-fbfff7ff] Max Packet=[2048] IR/IT contexts=[4/8]
> Jun 8 05:26:35 upstairs kernel: ohci_hcd 0000:02:0a.0: urb f71cb680 path 2 ep1in 5e160000 cc 5 --> status -62
> Jun 8 05:26:35 upstairs kernel: hub 1-2:1.0: transfer --> -62
> Jun 8 05:27:08 upstairs kernel: driver: '0000:02:0b.0': driver_bound: bound to device 'ohci1394'
> Jun 8 05:27:08 upstairs kernel: bus: 'pci': really_probe: bound device 0000:02:0b.0 to driver ohci1394
The log at http://lkml.org/lkml/2008/6/6/317 shows two pauses. One in
the middle of USB related messages with no FireWire stuff around
(17:25:19 to 17:25:44). The other with parport, ieee1394, USB messages
around it (17:25:44 to 17:26:31).
From there, the last 17:25:44 message is strange: The device
00110666000013cc which is the controller is reported as being removed.
Chris, did you do something at this point?
Also, in http://lkml.org/lkml/2008/6/1/2 you reported a patch which
changes the SCSI core's interaction with the driver core as first bad
commit. Did you check that going before this commit removes _all_ the
pauses, even those around USB or FireWire messages? Or did you only
check whether disk drives appear quickly?
--
Stefan Richter
-=====-==--- -==- -=--=
http://arcgraph.de/sr/
On Mon, 9 Jun 2008, Stefan Richter wrote:
> The log at http://lkml.org/lkml/2008/6/6/317 shows two pauses. One in
> the middle of USB related messages with no FireWire stuff around
> (17:25:19 to 17:25:44). The other with parport, ieee1394, USB messages
> around it (17:25:44 to 17:26:31).
>
> From there, the last 17:25:44 message is strange: The device
> 00110666000013cc which is the controller is reported as being removed.
> Chris, did you do something at this point?
It's also worth noting that the first 17:25:44 message is highly
suspicious. It is the initial output of the ohci-hcd driver,
indicating that the udev/hotplug system had just loaded that driver.
This doesn't seem to have anything to do with the SCSI stack.
Whatever caused the delay, it also managed to pause the other hotplug
task which was in the midst of loading uhci-hcd.
Alan Stern
2008/6/9 Alan Stern <[email protected]>:
> On Mon, 9 Jun 2008, Stefan Richter wrote:
>
Sorry folks, I'm unexpectedly away from the computers that these
"problems" occur on.
I should be back at home tomorrow and will answer you all as quickly
as possible then.
Thanks,
Chris
>> The log at http://lkml.org/lkml/2008/6/6/317 shows two pauses. One in
>> the middle of USB related messages with no FireWire stuff around
>> (17:25:19 to 17:25:44). The other with parport, ieee1394, USB messages
>> around it (17:25:44 to 17:26:31).
>>
>> From there, the last 17:25:44 message is strange: The device
>> 00110666000013cc which is the controller is reported as being removed.
>> Chris, did you do something at this point?
>
> It's also worth noting that the first 17:25:44 message is highly
> suspicious. It is the initial output of the ohci-hcd driver,
> indicating that the udev/hotplug system had just loaded that driver.
> This doesn't seem to have anything to do with the SCSI stack.
>
> Whatever caused the delay, it also managed to pause the other hotplug
> task which was in the midst of loading uhci-hcd.
>
> Alan Stern
>
>
--
Beauty is in the eye of the beerholder.
On Sun, Jun 08, 2008 at 01:37:56PM -0500, James Bottomley wrote:
> > 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).
What distro is this being seen on? I know that openSUSE 11.0 betas did
have a bug in their init scripts that was causing a long delay, much
like this one. But it has been fixed in the later releases
(hopefully...)
thanks,
greg k-h
On Monday 09 June 2008, Grant Grundler wrote:
> On Fri, Jun 6, 2008 at 10:35 AM, Chris Clayton <[email protected]>
wrote:
> >...
> > Yes, I still get the boot pause and the delay in desktop icons appearing
> > when a usb-storage device is plugged in with -rc5. A boot log is
> > attached. Is there some sort of verbose scsi boot messaging that I can
> > switch on? I've looked but I'm damned if I can find anything in 'make
> > menuconfig'.
>
> SCSI_CONSTANTS and SCSI_LOGGING might help.
> Both live in the SCSI options menu. Read the Kconfig help on how
> to use SCSI_LOGGING.
>
> Can you please also enable CONFIG_PRINTK_TIME ?
I've enabled CONFIG_PRINTK_TIME and will look into the SCSI options.
Thanks
>
> Using the timestamps in /var/log/messages is ok but not the most
> reliable place to get somewhat accurate time stamps of events.
>
> hth,
> grant
--
Beauty is in the eye of the beerholder.
On Monday 09 June 2008, Greg KH wrote:
> On Sun, Jun 08, 2008 at 01:37:56PM -0500, James Bottomley wrote:
> > > 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).
>
> What distro is this being seen on? I know that openSUSE 11.0 betas did
> have a bug in their init scripts that was causing a long delay, much
> like this one. But it has been fixed in the later releases
> (hopefully...)
>
As I repied to James a few minutes ago, 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.
Thanks
Chris
> thanks,
>
> greg k-h
--
Beauty is in the eye of the beerholder.
On Monday 09 June 2008, Stefan Richter wrote:
> Alan Stern wrote:
> > In fact the log shows that the 30-second delay occurs in the middle of
> > ohci1394 (Firewire) initialization, not USB initialization:
> >
> > Jun 8 05:26:35 upstairs kernel: ohci1394: fw-host0: OHCI-1394 1.1 (PCI):
> > IRQ=[22] MMIO=[fbfff000-fbfff7ff] Max Packet=[2048] IR/IT
> > contexts=[4/8] Jun 8 05:26:35 upstairs kernel: ohci_hcd 0000:02:0a.0:
> > urb f71cb680 path 2 ep1in 5e160000 cc 5 --> status -62 Jun 8 05:26:35
> > upstairs kernel: hub 1-2:1.0: transfer --> -62
> > Jun 8 05:27:08 upstairs kernel: driver: '0000:02:0b.0': driver_bound:
> > bound to device 'ohci1394' Jun 8 05:27:08 upstairs kernel: bus: 'pci':
> > really_probe: bound device 0000:02:0b.0 to driver ohci1394
>
> The log at http://lkml.org/lkml/2008/6/6/317 shows two pauses. One in
> the middle of USB related messages with no FireWire stuff around
> (17:25:19 to 17:25:44). The other with parport, ieee1394, USB messages
> around it (17:25:44 to 17:26:31).
>
> From there, the last 17:25:44 message is strange: The device
> 00110666000013cc which is the controller is reported as being removed.
> Chris, did you do something at this point?
Ah sorry, that's a legacy of when I had considerably less ram than 2GB. I only
use firewire on the rare occasion that I want to grab some video from my camera
and I use the parallel port even less frequently. So one of the last things
that happens in my rc.local init script is that I unload the related drivers.
>
> Also, in http://lkml.org/lkml/2008/6/1/2 you reported a patch which
> changes the SCSI core's interaction with the driver core as first bad
> commit. Did you check that going before this commit removes _all_ the
> pauses, even those around USB or FireWire messages? Or did you only
> check whether disk drives appear quickly?
When I was bisecting, I assessed good or bad based on whether I experienced the
long pause during boot up. You may have seen my reply to James a short while
ago that I have bisected again and arrived at the same patch.
Thanks,
Chris
--
Beauty is in the eye of the beerholder.
Chris Clayton wrote:
> I only
> use firewire on the rare occasion that I want to grab some video from my camera
> and I use the parallel port even less frequently. So one of the last things
> that happens in my rc.local init script is that I unload the related drivers.
On an unrelated note: If the driver was automatically loaded in a
hotplug-like fashion (based on PCI IDs and module aliases), you could
prevent it with "blacklist ohci1394" in one of the modprobe
configuration files.
--
Stefan Richter
-=====-==--- -==- -=-=-
http://arcgraph.de/sr/
[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
> >
> > <[email protected]> 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
> >
> > <[email protected]> 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.
On Tue, 10 Jun 2008, Chris Clayton wrote:
> 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.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
...
You can eliminate this 5-second delay by adding
options usb-storage delay_use=0
to /etc/modprobe.conf. Of course, this will make the other delays just
stand out that much more sharply...
Alan Stern
Hi everyone,
[snip]
> > 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).
[snip]
> I'll do so more poking about tomorrow night, but if anyone has any ideas in
> the meantime, I'd be very grateful.
>
I've done that poking around and found something that to me looks interesting.
Before plugging in a usb stick, I changed udev's log_priority to "debug" (using
udevcontrol). Attached is the snippet from /var/log/messages that shows all the
diagnostics emitted by udev when the stick was plugged in. (This is with
2.6.26-rc5-git5). You will see that there are several instances of a message
about udev unsuccesfully waiting for a file ioerr_cnt to appear deep down in
the guts of /sys. Eventually, it does appear, but only after 21 seconds have
elapsed. On 2.6.25.6, the file appears almost as soon as udev starts looking
for it. The log extract showing this is also attached as is an extract from the
kernel log for 2.6.26-rc5-git5.
By the way, the main udev-rules file that is installed is the one for slackware
that comes with the udev package from kernel.org. So the file these tests were
run with are that from udev-122, which I upgraded to earlier this evening (more
in hope than expectation :-)
--
Beauty is in the eye of the beerholder.
On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.0/host4/ioerr_cnt' for 20 mseconds
> Jun 11 17:48:18 upstairs last message repeated 236 times
This doesn't look good. It looks like a udev rule in your system is
looking for a file that will never show up. That's a short way to a
long delay time :)
Try commenting out the rule that does this and see if things are fixed.
thanks,
greg k-h
On Wed, 2008-06-11 at 12:15 -0700, Greg KH wrote:
> On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> > Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.0/host4/ioerr_cnt' for 20 mseconds
> > Jun 11 17:48:18 upstairs last message repeated 236 times
>
> This doesn't look good. It looks like a udev rule in your system is
> looking for a file that will never show up. That's a short way to a
> long delay time :)
>
> Try commenting out the rule that does this and see if things are fixed.
Actually, there's something seriously wrong here: ioerr_cnt is a
property of the device, not of the host (as in it will never appear
under .../host4 but under .../host4/targetX:X:X/4:X:X:X/ioerr_cnt).
Perhaps an investigation of why udevd-event is looking under host4/ is
in order.
James
James Bottomley wrote:
> On Wed, 2008-06-11 at 12:15 -0700, Greg KH wrote:
>> On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
>>> Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.0/host4/ioerr_cnt' for 20 mseconds
>>> Jun 11 17:48:18 upstairs last message repeated 236 times
>> This doesn't look good. It looks like a udev rule in your system is
>> looking for a file that will never show up. That's a short way to a
>> long delay time :)
>>
>> Try commenting out the rule that does this and see if things are fixed.
>
> Actually, there's something seriously wrong here: ioerr_cnt is a
> property of the device, not of the host (as in it will never appear
> under .../host4 but under .../host4/targetX:X:X/4:X:X:X/ioerr_cnt).
> Perhaps an investigation of why udevd-event is looking under host4/ is
> in order.
So the change which commit b0ed43360fdca227048d88a08290365cb681c1a8
"[SCSI] add scsi_host and scsi_target to scsi_bus" introduced is leading
the udev scripts onto a wrong trail?
(This commit was the one which Chris found by bisection, see
http://lkml.org/lkml/2008/6/1/2)
--
Stefan Richter
-=====-==--- -==- -=-==
http://arcgraph.de/sr/
On Wed, Jun 11, 2008 at 02:24:42PM -0500, James Bottomley wrote:
> On Wed, 2008-06-11 at 12:15 -0700, Greg KH wrote:
> > On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> > > Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.0/host4/ioerr_cnt' for 20 mseconds
> > > Jun 11 17:48:18 upstairs last message repeated 236 times
> >
> > This doesn't look good. It looks like a udev rule in your system is
> > looking for a file that will never show up. That's a short way to a
> > long delay time :)
> >
> > Try commenting out the rule that does this and see if things are fixed.
>
> Actually, there's something seriously wrong here: ioerr_cnt is a
> property of the device, not of the host (as in it will never appear
> under .../host4 but under .../host4/targetX:X:X/4:X:X:X/ioerr_cnt).
> Perhaps an investigation of why udevd-event is looking under host4/ is
> in order.
I blame a badly written udev rule :)
thanks,
greg k-h
On Wed, 2008-06-11 at 21:29 +0200, Stefan Richter wrote:
> James Bottomley wrote:
> > On Wed, 2008-06-11 at 12:15 -0700, Greg KH wrote:
> >> On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> >>> Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.0/host4/ioerr_cnt' for 20 mseconds
> >>> Jun 11 17:48:18 upstairs last message repeated 236 times
> >> This doesn't look good. It looks like a udev rule in your system is
> >> looking for a file that will never show up. That's a short way to a
> >> long delay time :)
> >>
> >> Try commenting out the rule that does this and see if things are fixed.
> >
> > Actually, there's something seriously wrong here: ioerr_cnt is a
> > property of the device, not of the host (as in it will never appear
> > under .../host4 but under .../host4/targetX:X:X/4:X:X:X/ioerr_cnt).
> > Perhaps an investigation of why udevd-event is looking under host4/ is
> > in order.
>
> So the change which commit b0ed43360fdca227048d88a08290365cb681c1a8
> "[SCSI] add scsi_host and scsi_target to scsi_bus" introduced is leading
> the udev scripts onto a wrong trail?
Yes, I think so ... what it does is make us get bus events for the
target as well as the lun, whereas without it we only get them for the
lun. I think something is misparsing the new target event and this is
where the trouble is coming from.
James
On Wednesday 11 June 2008, Greg KH wrote:
> On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> > Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for
> > '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.0/ho
> >st4/ioerr_cnt' for 20 mseconds Jun 11 17:48:18 upstairs last message
> > repeated 236 times
>
> This doesn't look good. It looks like a udev rule in your system is
> looking for a file that will never show up. That's a short way to a
> long delay time :)
>
> Try commenting out the rule that does this and see if things are fixed.
>
Yes, that's it. It's this rule, which appears as the second rule in the
slackware rules file that's distributed with udev (and it's been there since
udev-97 in August 2006):
ACTION=="add", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"
Commenting that rule out eliminates the pause in the boot and in the appearance
of icons on my desktop.
Thanks,
Chris
> thanks,
>
> greg k-h
--
Beauty is in the eye of the beerholder.
Chris Clayton wrote:
> On Wednesday 11 June 2008, Greg KH wrote:
>> Try commenting out the rule that does this and see if things are fixed.
>
> Yes, that's it. It's this rule, which appears as the second rule in the
> slackware rules file that's distributed with udev (and it's been there since
> udev-97 in August 2006):
>
> ACTION=="add", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"
>
> Commenting that rule out eliminates the pause in the boot and in the appearance
> of icons on my desktop.
It's called a workaround, not a fix.
--
Stefan Richter
-=====-==--- -==- -=-==
http://arcgraph.de/sr/
Chris Clayton wrote:
> It's this rule, which appears as the second rule in the
> slackware rules file that's distributed with udev (and it's been there since
> udev-97 in August 2006):
>
> ACTION=="add", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"
>
> Commenting that rule out eliminates the pause in the boot and in the appearance
> of icons on my desktop.
FWIW, Gentoo's udev 119 has this:
$ grep -r ioerr_cnt /etc/udev/
/etc/udev/rules.d/05-udev-early.rules:ACTION=="add",
KERNEL=="[0-9]*:[0-9]*", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"
Whatever this rule is good for... Maybe the pattern should be
"[0-9]+(:[0-9]+){3}" to match logical units only.
--
Stefan Richter
-=====-==--- -==- -=-==
http://arcgraph.de/sr/
I wrote:
> /etc/udev/rules.d/05-udev-early.rules:ACTION=="add",
> KERNEL=="[0-9]*:[0-9]*", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"
>
> Whatever this rule is good for... Maybe the pattern should be
> "[0-9]+(:[0-9]+){3}" to match logical units only.
Actually no; looks like these are just glob(7) patterns. Then the
pattern might already be OK since host devices' and target devices'
names don't start with decimal numbers.
--
Stefan Richter
-=====-==--- -==- -=-==
http://arcgraph.de/sr/
Hi James,
On Wednesday 11 June 2008, James Bottomley wrote:
> On Wed, 2008-06-11 at 21:29 +0200, Stefan Richter wrote:
> > James Bottomley wrote:
> > > On Wed, 2008-06-11 at 12:15 -0700, Greg KH wrote:
> > >> On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> > >>> Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for
> > >>> '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.
> > >>>0/host4/ioerr_cnt' for 20 mseconds Jun 11 17:48:18 upstairs last
> > >>> message repeated 236 times
> > >>
> > >> This doesn't look good. It looks like a udev rule in your system is
> > >> looking for a file that will never show up. That's a short way to a
> > >> long delay time :)
> > >>
> > >> Try commenting out the rule that does this and see if things are
> > >> fixed.
> > >
> > > Actually, there's something seriously wrong here: ioerr_cnt is a
> > > property of the device, not of the host (as in it will never appear
> > > under .../host4 but under .../host4/targetX:X:X/4:X:X:X/ioerr_cnt).
> > > Perhaps an investigation of why udevd-event is looking under host4/ is
> > > in order.
> >
> > So the change which commit b0ed43360fdca227048d88a08290365cb681c1a8
> > "[SCSI] add scsi_host and scsi_target to scsi_bus" introduced is leading
> > the udev scripts onto a wrong trail?
>
> Yes, I think so ... what it does is make us get bus events for the
> target as well as the lun, whereas without it we only get them for the
> lun. I think something is misparsing the new target event and this is
> where the trouble is coming from.
>
I assume that since we now the source of this problem, you can create it at
will. I only mention because if you need me to test a patch, it will have to be
before Tuesday, June 17 - I go on holiday (vacation) on that day.
Thanks
Chris
> James
--
Beauty is in the eye of the beerholder.
On Fri, 2008-06-13 at 06:56 +0000, Chris Clayton wrote:
> Hi James,
>
> On Wednesday 11 June 2008, James Bottomley wrote:
> > On Wed, 2008-06-11 at 21:29 +0200, Stefan Richter wrote:
> > > James Bottomley wrote:
> > > > On Wed, 2008-06-11 at 12:15 -0700, Greg KH wrote:
> > > >> On Wed, Jun 11, 2008 at 06:58:05PM +0000, Chris Clayton wrote:
> > > >>> Jun 11 17:48:13 upstairs udevd-event[1457]: wait_for_sysfs: wait for
> > > >>> '/sys/devices/pci0000:00/0000:00:1e.0/0000:02:0a.2/usb11/11-2/11-2:1.
> > > >>>0/host4/ioerr_cnt' for 20 mseconds Jun 11 17:48:18 upstairs last
> > > >>> message repeated 236 times
> > > >>
> > > >> This doesn't look good. It looks like a udev rule in your system is
> > > >> looking for a file that will never show up. That's a short way to a
> > > >> long delay time :)
> > > >>
> > > >> Try commenting out the rule that does this and see if things are
> > > >> fixed.
> > > >
> > > > Actually, there's something seriously wrong here: ioerr_cnt is a
> > > > property of the device, not of the host (as in it will never appear
> > > > under .../host4 but under .../host4/targetX:X:X/4:X:X:X/ioerr_cnt).
> > > > Perhaps an investigation of why udevd-event is looking under host4/ is
> > > > in order.
> > >
> > > So the change which commit b0ed43360fdca227048d88a08290365cb681c1a8
> > > "[SCSI] add scsi_host and scsi_target to scsi_bus" introduced is leading
> > > the udev scripts onto a wrong trail?
> >
> > Yes, I think so ... what it does is make us get bus events for the
> > target as well as the lun, whereas without it we only get them for the
> > lun. I think something is misparsing the new target event and this is
> > where the trouble is coming from.
> >
>
> I assume that since we now the source of this problem, you can create it at
> will. I only mention because if you need me to test a patch, it will have to be
> before Tuesday, June 17 - I go on holiday (vacation) on that day.
Yes, we can; thanks!
The problem though is that it's in the udev scripts, so there's nothing
we can fix in the kernel, we now need to persuade the various distros to
fix it (if they're actually broken), so it might take a while.
James
On Wednesday 11 June 2008, Stefan Richter wrote:
> I wrote:
> > /etc/udev/rules.d/05-udev-early.rules:ACTION=="add",
> > KERNEL=="[0-9]*:[0-9]*", SUBSYSTEM=="scsi", WAIT_FOR_SYSFS="ioerr_cnt"
> >
> > Whatever this rule is good for... Maybe the pattern should be
> > "[0-9]+(:[0-9]+){3}" to match logical units only.
>
> Actually no; looks like these are just glob(7) patterns. Then the
> pattern might already be OK since host devices' and target devices'
> names don't start with decimal numbers.
For Slackware 12.0.0, the rule is:
ACTION=="add", KERNEL=="[0-9]*:[0-9]*", SUBSYSTEM=="scsi",
WAIT_FOR_SYSFS="ioerr_cnt"
Using that rule instaed of the old one in the Slackware rules file included with
udev appears to result in the same behaviour as with the old rule and kernel <
2.6.26.
Unless someone warns me otherwise, I think I'll go with that on my (homebrewed)
system, so thanks to everyone for your help.
Chris
--
Beauty is in the eye of the beerholder.