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

From: jim owens
Date: Wed May 27 2009 - 14:07:48 EST

Martin Knoblauch wrote:
----- 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 :-)

No idea what is going on, but since I saw your May 20 message,
I have been trying to wake up someone whose day job it should
be to care about dl380s and smartarrays. :)

If they don't react soon, I'll make this my own day job to
try to reproduce it. We will need hardware config details and
firmware revs to start.

So I would not close the bug just yet.

jim

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