Re: Analyzed/Solved/Bisected: Booting 2.6.30-rc2-git7 very slow

[Martin Knoblauch]

----- Original Message ----

> From: Matthew Wilcox <matthew@xxxxxx>
> To: Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx>
> Cc: Martin Knoblauch <knobi@xxxxxxxxxxxx>; Mike Galbraith <efault@xxxxxx>; viro@xxxxxxxxxxxxxxxxxx; rjw@xxxxxxx; linux-kernel@xxxxxxxxxxxxxxx; tigran@xxxxxxxxxxxxxxxxxxxxx; Kay Sievers <kay.sievers@xxxxxxxx>; shemminger@xxxxxxxxxx; Jesse Barnes <jbarnes@xxxxxxxxxxxxxxxx>
> Sent: Wednesday, May 27, 2009 1:21:53 PM
> Subject: Re: Analyzed/Solved/Bisected: Booting 2.6.30-rc2-git7 very slow
> 
> On Tue, May 26, 2009 at 11:31:02PM -0700, Andrew Morton wrote:
> > On Wed, 20 May 2009 03:22:28 -0700 (PDT) Martin Knoblauch 
> wrote:
> > 
> > > 
> > > ----- Original Message ----
> > > 
> > > > From: Mike Galbraith 
> > > > To: Martin Knoblauch 
> > > > Cc: Andrew Morton ; viro@xxxxxxxxxxxxxxxxxx; 
> rjw@xxxxxxx; linux-kernel@xxxxxxxxxxxxxxx; tigran@xxxxxxxxxxxxxxxxxxxx
> > > > Sent: Wednesday, May 6, 2009 10:37:45 AM
> > > > Subject: Re: Analyzed/Solved: Booting 2.6.30-rc2-git7 very slow
> > > > 
> > > > On Wed, 2009-05-06 at 00:55 -0700, Martin Knoblauch wrote:
> > > > 
> > > > >  just to bring this back to my problem :-)
> > > > 
> > > > Good idea :-)
> > > > 
> > > > >  Last week I reported that the "new" sysfs entry in /proc/mounts already 
> comes 
> > > > out of initrd. Does this ring a bell?
> > > > > 
> > > > > http://lkml.indiana.edu/hypermail/linux/kernel/0904.3/03048.html
> > > > 
> > > > Nope, no bells.
> > > > 
> > > > The only thing I can suggest is that you try a bisection.
> > > > 
> > > >     -Mike
> > > 
> > >  OK, so I finally managed to bisect the issue down to the following commit. 
> Not much that I can say about it. Someone else suggested that it might all be a 
> question of timing. Might very well be. I will try it out on a system with a 
> different SCSI/RAID controller. The failing system has an "Smart Array 6i" 
> (cciss). "cciss", "ext3" and "jbd" are all modules coming from initrd.
> > > 
> > > |commit 1120f8b8169fb2cb51219d326892d963e762edb6
> > > |Author: Stephen Hemminger 
> > > |Date:   Thu Dec 18 09:17:16 2008 -0800
> > > |
> > > |    PCI: handle long delays in VPD access
> > > |
> > > |    Accessing the VPD area can take a long time.  The existing
> > > |    VPD access code fails consistently on my hardware. There are comments
> > > |
> > > |    Change the access routines to:
> > > |      * use a mutex rather than spinning with IRQ's disabled and lock held
> > > |      * have a much longer timeout
> > > |      * call cond_resched while spinning
> > > |
> > > |    Signed-off-by: Stephen Hemminger 
> > > |    Reviewed-by: Matthew Wilcox 
> > > |    Signed-off-by: Jesse Barnes 
> > > 
> > 
> > 
> 
> This is the first I've seen of this report ...
> 
> > So afacit what's happening is that the above change caused one of your
> > PCI devices to take a very long time to initialise, yes?  Was it the
> > CCISS driver?
> > 
> > If you add "printk.time=y" to the kernel boot command line then you'll
> > get timestamped boot messages which will make it easier to determine
> > where the time was consumed.  Adding `initcall_debug' to the boot line
> > will help us delve further into the delay, assuming that the offending
> > driver is build into vmlinux (which it might not be).
> 
> The two message logs posted show NTP starting up within a second of
> each other.  What was the problem again?
> 

 Just to recap. Starting with 2.6.29-rc1, /proc/mounts has two "sysfs" lines:

|none /sys sysfs rw,relatime 0 0
| /sys /sys sysfs rw,relatime 0 0

 The first of them already comes out of initrd, which somehow means that the explicit umount in the initrd/init script seems to fail. This is observable on a HP/DL380G4 with a "SmartArray 6" controller (cciss driver).

 As a result of the two lines, the hotplug/firmware script in my RHEL4.3 userspace failed to determine the "/sys" mountpoint, which in turn resulted in a 60 second timeout for each firmware load attempt, adding 6 minutes to the boot sequence (4 CPUs, 2 tg3s). I have since then just fixed the hotplug script to do "the right thing". Therefore you are not seeing a big difference in the two posted dmesg logs. The underlying issue remains.

 In a next step I managed to bisect the appearance of the second "sysfs" line down to the following commit:

|commit 1120f8b8169fb2cb51219d326892d963e762edb6
|Author: Stephen Hemminger <shemminger@xxxxxxxxxx>
|Date:   Thu Dec 18 09:17:16 2008 -0800
|
|    PCI: handle long delays in VPD access
|
|    Accessing the VPD area can take a long time.  The existing
|    VPD access code fails consistently on my hardware. There are comments
|
|    Change the access routines to:
|      * use a mutex rather than spinning with IRQ's disabled and lock held
|      * have a much longer timeout
|      * call cond_resched while spinning
|
|    Signed-off-by: Stephen Hemminger <shemminger@xxxxxxxxxx>
|    Reviewed-by: Matthew Wilcox <willy@xxxxxxxxxxxxxxx>
|    Signed-off-by: Jesse Barnes <jbarnes@xxxxxxxxxxxxxxxx>

 The commit itself may just show a problem/bug elsewhere. It definitely changes locking and timing around PCI.

 Next, I tried to run an identically configured kernel on a different system (IBM/x3650 with aacraid). The problem was not observable. This now either points to CCISS, or leaves timing.

 Finally, today I built the ccsii driver into the kernel. It was previously modularized and loaded from initrd. The second "sysfs" line went away. But does this make cciss guilty? It is now loaded about 2 seconds earlier in the boot sequence, which is a big change in timing I guess.

 Enlighten me :-)

Cheers
Martin
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/