2.6.12 initrd module loading seems parallel on bootup

2.6.12 initrd module loading seems parallel on bootup

[Darryl L. Miles]

I'm witnessing a problem with mounting root on a system that loads 
modules from initrd in order to be able to mount root, this problem does 
not exist in 2.6.11.12 but does in 2.6.12 and 2.6.12.1.  Its as-if the 
modprobe/insmod from the initrd mini-root is loading the modules in 
parallel rather than in series.  The machine is SMP too.

The printk output over the console indicates the module loading is 
happening in parallel, as I can clearly see different driver bootup 
messages out of their expected order.

During bootup synchronous behavior is needed so that the drivers can be 
loaded in the order to allow auto-detection to occur at each stage in 
order to resolve root, in my case:

Loading scsi_mod.ko module
Loading sd_mod.ko module
Loading scsi_transport_spi.ko module
Loading sym53c8xx.ko module
Loading cpqarray.ko module
Loading raid1.ko module
Loading jbd.ko module
Loading ext3.ko module

For an EXT3 fs over /dev/md0 over sym53x8xx SCSI bus.


Maybe this problem is a userspace problem, like an extra option needed 
to insmod to make is wait ?  Please advise.

-- 
Darryl L. Miles

Re: 2.6.12 initrd module loading seems parallel on bootup

[Darryl L. Miles]

The kernel is panic'ed trying to mount even before the sym53c8xx driver 
has completed SCSI bus detection, the MD driver does not find any 
volumes (since neither the cpqarray.ko or sym53c8xx.ko have registered 
any disks on the system yet).

I have also witnessed (when booting 2.6.12.1) what appeared to be 
ext3.ko load failure, I think due to jbd.ko not having chance to 
register its exported symbols before ext3.ko needs to find them.


The broken sequence on 2.6.12 (excuse any errors, this has been typed in 
not pasted) it would be handy to allow Shift-Page Up to work from a 
panic, "unable to mount root" or "unable to exec init" if that were 
possible.

You can see the out of place "input: AT Translated Set 2 keyboard on 
isa0060/serio0" and "Compaq SMART2 Driver (v 2.6.0)" the elapsed time to 
print all these messages is < 1.5 seconds.

RedHat nash version 4.1.18 stable
Mounting /proc filesystem
Mounting sysfs
Creating /dev
Starting udev
input: AT Translated Set 2 keyboard on isa0060/serio0
Loading scsi_mod.ko module
Loading sd_mod.ko module
SCSI subsystem initialized
Loading scsi_transport_spi.ko module
Loading sym53c8xx.ko module
Loading cpqarray.ko module
Loading raid1.ko module
Loading jbd.ko module
Loading ext3.ko module
ACPI: PCI interrupt 0000:05:04.0[A] -> GSI 22 (level, low) -> IRQ 169
sym0: <896> rev 0x5 at pci 0000:05:04.0 irq 177
Compaq SMART2 Driver (v 2.6.0)
sym0: No NVRAM, ID 7, Fast-40, LVD, parity checking
sym0: SCSI BUS has been reset.
scsi0 : sym-2.2.0
md: raid1 personality registered as nr 3
md: Autodetecting RAID arrays.
md: ... autorun DONE.
md: Autodetecting RAID arrays.
md: autorun ...
md: ... autorun DONE.
md: Autodetecting RAID arrays.
md: autorun ...
md: ... autorun DONE.

Creating root device
Mounting root filesystem
mount: error 19 mounting ext3
mount: error 2 mounting none
Switching to new root
switchroot: mount failed: 22
umount /initrd /dev failed: 2
kernel panic - not syncing: Attempted to kill init!
<0>Rebooting in 240 seconds...



The following is what a healthy 2.6.11.12 bootup on the same system looks like:


Freeing unused kernel memory: 232k freed
SCSI subsystem initialized
Compaq SMART2 Driver (v 2.6.0)
cpqarray: Device 0xae10 has been found at bus 6 dev 0 func 0
ACPI: PCI interrupt 0000:06:00.0[A] -> GSI 30 (level, low) -> IRQ 169
cpqarray: Finding drives on ida0 (Smart Array 3200)
cpqarray ida/c0d0: blksz=512 nr_blks=35561280
cpqarray ida/c0d1: blksz=512 nr_blks=71130720
cpqarray ida/c0d2: blksz=512 nr_blks=17764320
cpqarray ida/c0d3: blksz=512 nr_blks=35838720
 ida/c0d0: p1 p2
 ida/c0d1: p1
 ida/c0d2: p1 p2
 ida/c0d3: p1
ACPI: PCI interrupt 0000:05:04.0[A] -> GSI 22 (level, low) -> IRQ 177
sym0: <896> rev 0x5 at pci 0000:05:04.0 irq 177
sym0: No NVRAM, ID 7, Fast-40, LVD, parity checking
sym0: SCSI BUS has been reset.
scsi0 : sym-2.1.18n
  Vendor: COMPAQ    Model: BD30088279        Rev: HPB0
  Type:   Direct-Access                      ANSI SCSI revision: 03
sym0:0:0: tagged command queuing enabled, command queue depth 16.
 target0:0:0: Beginning Domain Validation
sym0:0: wide asynchronous.
sym0:0: FAST-40 WIDE SCSI 80.0 MB/s ST (25.0 ns, offset 31)
 target0:0:0: Ending Domain Validation
SCSI device sda: 585937500 512-byte hdwr sectors (300000 MB)
SCSI device sda: drive cache: write through
SCSI device sda: 585937500 512-byte hdwr sectors (300000 MB)
SCSI device sda: drive cache: write through
 sda: sda1 sda2 sda3 sda4
Attached scsi disk sda at scsi0, channel 0, id 0, lun 0
  Vendor: COMPAQ    Model: BD30088279        Rev: HPB0
  Type:   Direct-Access                      ANSI SCSI revision: 03
sym0:4:0: tagged command queuing enabled, command queue depth 16.
 target0:0:4: Beginning Domain Validation
sym0:4: wide asynchronous.
sym0:4: FAST-40 WIDE SCSI 80.0 MB/s ST (25.0 ns, offset 31)
 target0:0:4: Ending Domain Validation
SCSI device sdb: 585937500 512-byte hdwr sectors (300000 MB)
SCSI device sdb: drive cache: write through
SCSI device sdb: 585937500 512-byte hdwr sectors (300000 MB)
SCSI device sdb: drive cache: write through
SCSI device sdb: drive cache: write through
 sdb: sdb1 sdb2 sdb3 sdb4
Attached scsi disk sdb at scsi0, channel 0, id 4, lun 0
ACPI: PCI interrupt 0000:05:04.1[B] -> GSI 21 (level, low) -> IRQ 185
sym1: <896> rev 0x5 at pci 0000:05:04.1 irq 185
sym1: No NVRAM, ID 7, Fast-40, LVD, parity checking
sym1: SCSI BUS has been reset.
scsi1 : sym-2.1.18n
md: raid1 personality registered as nr 3
md: Autodetecting RAID arrays.
md: invalid raid superblock magic on sda4
md: sda4 has invalid sb, not importing!
md: invalid raid superblock magic on sdb4
md: sdb4 has invalid sb, not importing!
md: autorun ...
md: considering sdb3 ...
md:  adding sdb3 ...
md: sdb2 has different UUID to sdb3
md: sdb1 has different UUID to sdb3
md:  adding sda3 ...
md: sda2 has different UUID to sdb3
md: sda1 has different UUID to sdb3
md: created md2
md: bind<sda3>
md: bind<sdb3>
md: running: <sdb3><sda3>
raid1: raid set md2 active with 2 out of 2 mirrors
md: considering sdb2 ...
md:  adding sdb2 ...
md: sdb1 has different UUID to sdb2
md:  adding sda2 ...
md: sda1 has different UUID to sdb2
md: created md0
md: bind<sda2>
md: bind<sdb2>
md: running: <sdb2><sda2>
raid1: raid set md0 active with 2 out of 2 mirrors
md: considering sdb1 ...
md:  adding sdb1 ...
md:  adding sda1 ...
md: created md1
md: bind<sda1>
md: bind<sdb1>
md: running: <sdb1><sda1>
raid1: raid set md1 active with 2 out of 2 mirrors
md: ... autorun DONE.
md: Autodetecting RAID arrays.
md: autorun ...
md: ... autorun DONE.
md: Autodetecting RAID arrays.
md: autorun ...
md: ... autorun DONE.
kjournald starting.  Commit interval 5 seconds
EXT3-fs: mounted filesystem with ordered data mode.

Hope this helps


-- 
Darryl L. Miles

Re: 2.6.12 initrd module loading seems parallel on bootup

[Christian Trefzer]

[-- Attachment #1: Type: text/plain, Size: 1142 bytes --]

Well, although I cannot comment on your exact situation, I guess I see 
the same problem here. When checking out 2.6.12 for the first time, my 
little early-userspace environment had some serious trouble configuring 
the scsi|md|lvm setup which worked flawlessly before. The plan was to 
load required modules for disks, then md, bring up the arrays and 
activate the LVs. But it takes several seconds (!) until device nodes 
appear after modprobe has terminated correctly. For me, the quick ugly 
fix was to introduce a delay loop in the bash scripts which waits for 
important device nodes before proceeding, similar to that:

function wait_for_node{} (
	echo -en "Waiting for ${1} to appear..."
	while [ ! -e ${1} ]
	do
		echo -en "."
		sleep 1s
	done
	echo " done."
)

This one can be called with any node important for the next 
initialization step. In my case, I wait for disk partitions to appear 
before RAID initialization:
	wait_for_node /dev/sda1
You could wait for your root partition to come up, instead of running 
into the vfs panic while trying to mount it. But that won't solve the 
original problem, I fear...

Yours,
Chris

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 894 bytes --]

Re: 2.6.12 initrd module loading seems parallel on bootup

[Andrew Morton]

"Darryl L. Miles" <darryl@netbauds.net> wrote:
>
> [ modules getting loaded out-of-order and in parallel from initrd ]
>

On June 7, Martin Wilck reported:

> It turned out to be a problem with Red Hat's nash that didn't check the 
> returned pid in it's wait4() call and thus ended up insmod'ing mutliple 
> modules simultaneously, leading to "Unkown symbol" errors. Yuck, it took 
> me a day figure that out.
> 
> That bug is fixed in redhat's "mkinitrd" package 4.2.0.3-1 and later, 
> but that package is currently only in Fedora's "Development" tree.

I'd like to know what changed in the kernel to make nash's behaviour
change.  Martin, did you work that out?

Re: 2.6.12 initrd module loading seems parallel on bootup

[Pozsár Balázs]

On Sat, Jun 25, 2005 at 11:46:11PM -0700, Andrew Morton wrote:
> I'd like to know what changed in the kernel to make nash's behaviour
> change.  Martin, did you work that out?

See http://lkml.org/lkml/2005/1/17/132


-- 
pozsy

Re: 2.6.12 initrd module loading seems parallel on bootup

[Darryl L. Miles]

Andrew Morton wrote:

>"Darryl L. Miles" <darryl@netbauds.net> wrote:
>  
>
>>[ modules getting loaded out-of-order and in parallel from initrd ]
>>    
>>
>
>On June 7, Martin Wilck reported:
>  
>
>>It turned out to be a problem with Red Hat's nash that didn't check the 
>>returned pid in it's wait4() call and thus ended up insmod'ing mutliple 
>>modules simultaneously, leading to "Unkown symbol" errors. Yuck, it took 
>>me a day figure that out.
>>
>>That bug is fixed in redhat's "mkinitrd" package 4.2.0.3-1 and later, 
>>but that package is currently only in Fedora's "Development" tree.
>>    
>>

Found the thread:   
http://www.ussg.iu.edu/hypermail/linux/kernel/0506.0/1556.html


This works for me:

wget 
http://download.fedora.redhat.com/pub/fedora/linux/core/development/i386/SRPMS/udev-058-1.src.rpm
rpmbuild --rebuild udev-058-1.src.rpm
rpm -Uvh /usr/src/redhat/RPMS/i386/udev-058-1.i386.rpm

wget 
http://download.fedora.redhat.com/pub/fedora/linux/core/development/i386/SRPMS/mkinitrd-4.2.17-1.src.rpm
rpmbuild --rebuild mkinitrd-4.2.17-1.src.rpm
rpm -Uvh /usr/src/redhat/RPMS/i386/mkinitrd-4.2.17-1.i386.rpm

Thanks


-- 
Darryl L. Miles

Re: 2.6.12 initrd module loading seems parallel on bootup

[Christian Trefzer]

[-- Attachment #1: Type: text/plain, Size: 356 bytes --]

Pozsár Balázs schrieb:
> See http://lkml.org/lkml/2005/1/17/132
The patch was against 2.6.11-rc1, has it not been adapted into mainline? 
As far as I can see, most of the hunks were already applied, and some 
parts of the code have evolved further since. BTW, I never had this 
problem with any 2.6.11 until .12 so far.
Thanks for your pointer!


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 894 bytes --]

Re: 2.6.12 initrd module loading seems parallel on bootup

[Christian Trefzer]

[-- Attachment #1: Type: text/plain, Size: 621 bytes --]

Darryl L. Miles schrieb:
> Andrew Morton wrote:

[snip]

> Found the thread:   
> http://www.ussg.iu.edu/hypermail/linux/kernel/0506.0/1556.html
> 
> 
> This works for me:
> 

[snip]

Thanks, but still no go, as I am using Gentoo and a totally bloated 
self-grown glibc initramfs environment. Whenever I boot 2.6.11.12, there 
is no problem whatsoever about modprobe returning before device nodes 
are created. Any ideas? I changed udev versions back and forth between 
058 and 056, did not make any difference either...

I can send any information of interest later tonight, but have to run 
for now. Thanks in advance!

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 894 bytes --]

Re: 2.6.12 initrd module loading seems parallel on bootup

[Parag Warudkar]

On Sunday 26 June 2005 02:46, Andrew Morton wrote:
> I'd like to know what changed in the kernel to make nash's behaviour
> change.  Martin, did you work that out?
Quoting from Prarit Bhargava's email (http://lkml.org/lkml/2005/6/14/149)
-
"The issue is that David Howells posted a patch that changed the behaviour of 
kallsyms/insmod/rmmod sometime ago.  The patch *is correct* in what it does, 
however, the patch requires that /sbin/sh must be aware of pid returns by 
wait() - http://lkml.org/lkml/2005/1/17/132"

IIRC this issue was same as the one faced by Martin.

Parag

Re: 2.6.12 initrd module loading seems parallel on bootup

[Toon van der Pas]

On Sun, Jun 26, 2005 at 02:00:05PM +0200, Christian Trefzer wrote:
> Darryl L. Miles schrieb:
> >Andrew Morton wrote:
> 
> [snip]
> 
> >Found the thread:   
> >http://www.ussg.iu.edu/hypermail/linux/kernel/0506.0/1556.html
> >
> >
> >This works for me:
> >
> 
> [snip]
> 
> Thanks, but still no go, as I am using Gentoo and a totally bloated 
> self-grown glibc initramfs environment. Whenever I boot 2.6.11.12, there 
> is no problem whatsoever about modprobe returning before device nodes 
> are created. Any ideas? I changed udev versions back and forth between 
> 058 and 056, did not make any difference either...

Well, I'm running Gentoo Linux x86_64 with a 2.6.12 kernel.
I didn't experience any problems. I use initrd because most
filesystems are located on LVM partitions.
I build my kernel with the following command:

	genkernel --no-mrproper --oldconfig --lvm2 --udev all

Work like a charm.
Regards,
Toon.

Re: 2.6.12 initrd module loading seems parallel on bootup

[Darryl L. Miles]

Are we sure we are not talking about two different problems here.

I'm using RedHat and mkinitrd, in the initrd image there is already a 
skeleton /dev tree that contains my real-root device.  udev also exists 
in the initrd image.  I don't think any /dev device magic was necessary 
for me too mount root.

It is not clear Chris which tools you are using on initrd, standard 
Gentoo methods or a home brew setup ?  What shell is calling modprobe ?  
Can you confirm at what point you are seeing modprobe exit ?

* Immediatly (before device driver has detected hardware and reported / 
registered its findings).  This is the symptom I was seeing, but the 
cause was incorrect shell handling. 
* After detection but before device node creation.
* After device node creation.


FYI - This looks like the snippet from nash.c

@@ -403,7 +450,7 @@
 int otherCommand(char * bin, char * cmd, char * end, int doFork) {
     char ** args;
     char ** nextArg;
-    int pid;
+    int pid, wpid;
     int status;
     char fullPath[255];
     static const char * sysPath = PATH;
@@ -479,10 +526,20 @@

        close(stdoutFd);

-       wait4(-1, &status, 0, NULL);
-       if (!WIFEXITED(status) || WEXITSTATUS(status)) {
-           printf("ERROR: %s exited abnormally!\n", args[0]);
-           return 1;
+       for (;;) {
+            wpid = wait4(-1, &status, 0, NULL);
+            if (wpid == -1) {
+                 printf("ERROR: Failed to wait for process %d\n", wpid);
+            }
+
+            if (wpid != pid)
+                 continue;
+
+            if (!WIFEXITED(status) || WEXITSTATUS(status)) {
+                 printf("ERROR: %s exited abnormally with value %d ! (pid %d)\n", args[0], WEXITSTATUS(status), pid);
+                 return 1;
+            }
+            break;
        }
     }


-- 
Darryl L. Miles

Re: 2.6.12 initrd module loading seems parallel on bootup

[Martin Wilck]

Pozsár Balázs wrote:

>>I'd like to know what changed in the kernel to make nash's behaviour
>>change.  Martin, did you work that out?
> 
> 
> See http://lkml.org/lkml/2005/1/17/132

I am not sure if it was the culprit. The problem was that nash is
running as init() with PID 1 and therefore all processes are its child
processes. Thus a fairly normal code such as

if (fork())
	wait4(-1...)

that would work under normal circumstances (there are no other real
children) can fail here. The terminating "children" that were
interfering here were all udev processes as far as I observed. I suppose
that inserting a module triggers udev which spawns a process which may
under certain circumstances terminate earlier than the insmod itself.

nash could also have solved the problem simply by fork()ing itself once
before doing any real work, so that it wouldn't run with pid 1.

Regards
Martin

Re: 2.6.12 initrd module loading seems parallel on bootup

[Christian Trefzer]

[-- Attachment #1: Type: text/plain, Size: 2383 bytes --]

Hi Darry,
first of all thanks for your questions, and sorry for answering late, 
I've been away for some time.

Darryl L. Miles schrieb:
> 
> Are we sure we are not talking about two different problems here.
> 
> I'm using RedHat and mkinitrd, in the initrd image there is already a 
> skeleton /dev tree that contains my real-root device.  udev also exists 
> in the initrd image.  I don't think any /dev device magic was necessary 
> for me too mount root.
> 
> It is not clear Chris which tools you are using on initrd, standard 
> Gentoo methods or a home brew setup ?  What shell is calling modprobe ?  
> Can you confirm at what point you are seeing modprobe exit ?

I am using a self-made initramfs setup using the "standard" binaries 
from the live system, usable for instance as rescue system with tools 
identical to anything I have installed, including bash as shell for the 
init script, udev, module-init-tools, lvm2, mdadm, and so on and so 
forth. There are only the most basic device nodes in the supplied /dev 
tree, like null, console, etc.
Unfortunately, I don't really "see" modprobe exit, it just takes less 
time until the "modprobe $mod && e_done" prints its "done." yet related 
device nodes are still missing. Waiting for any required nodes fixes the 
problem so far, but maybe bash-3.00 is having a similar issue as nash. 
I'll try using sash or busybox ASAP to check if the problem is somewhere 
else.

The funny thing is that with kernels up to 2.6.11.12, I don't see this 
problem. The patch mentioned further up this thread was against 
2.6.11-rc1 and should have been applied long before I even touched 
2.6.11, so I just don't understand why I have problems now.

> * Immediatly (before device driver has detected hardware and reported / 
> registered its findings).  This is the symptom I was seeing, but the 
> cause was incorrect shell handling. * After detection but before device 
> node creation.

Well, so far I cannot distinguish both of these cases, but it definitely 
is _not_ the third one:

> * After device node creation.
> 
> 
Otherwise I would not run into problems like mdadm failing trying to 
assemble arrays while disk nodes are still missing in action.

> FYI - This looks like the snippet from nash.c
> 
> [snip]

Thanks for the patch, I'll look into similarities in the bash code if 
the shell really is the cause of my trouble.

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 894 bytes --]

Re: 2.6.12 initrd module loading seems parallel on bootup

[Darryl L. Miles]

The exact patch for kernel/module.c that was marked for 2.6.11-rcX hit 
general release in patch-2.6.12.

What $PID is bash running as ?  Martin's comments on this are seem most 
relevant.

Can you build your own (2 pages of code) init process, that does 
something along the lines of
 * gracefully handles SIGCHLD
 * forks
 * executes bash
 * waits for bash to exit much like the patch does

So bash is not running a pid 1.  While nash is expected to run as init, 
bash is not, so fixing bash might also break it (its a complex beast).

-- 
Darryl L. Miles

Re: 2.6.12 initrd module loading seems parallel on bootup

[Christian Trefzer]

[-- Attachment #1: Type: text/plain, Size: 1259 bytes --]

Darryl L. Miles schrieb:
> 
> The exact patch for kernel/module.c that was marked for 2.6.11-rcX hit 
> general release in patch-2.6.12.
That explains a lot. Thanks for clarification : )

> What $PID is bash running as ?  Martin's comments on this are seem most 
> relevant.
The initramfs contains /init which is a shell script, while /bin/sh is 
bash. So I figure bash is running with PID 1, but I'll verify that by 
adding echo $$ to the init script.

> Can you build your own (2 pages of code) init process, that does 
> something along the lines of
> * gracefully handles SIGCHLD
> * forks
> * executes bash
> * waits for bash to exit much like the patch does
> 
> So bash is not running a pid 1.  While nash is expected to run as init, 
> bash is not, so fixing bash might also break it (its a complex beast).
> 
I'm not (yet) too much into C programming, so I'm afraid I won't be able 
to do that. As this problem arises only due to my own early-userspace 
setup, I'd rather try using different shells for init-as-shell-script, 
and maybe do some not-so-clean hacks to get the bigger picture.

As this is not a kernel issue, I'd rather take this one off LKML and 
write a success report once appropriate.

Thanks for your help to everyone involved : )


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 894 bytes --]