Messages in this thread | | | Date | Thu, 27 Dec 2007 12:42:35 +0100 | From | "Torsten Kaiser" <> | Subject | Re: 2.6.24-rc6-mm1 |
| |
On Dec 23, 2007 9:39 PM, Andrew Morton <akpm@linux-foundation.org> wrote: > > On Sun, 23 Dec 2007 17:27:12 +0100 "Torsten Kaiser" <just.for.lkml@googlemail.com> wrote: > > > On Dec 23, 2007 8:30 AM, Andrew Morton <akpm@linux-foundation.org> wrote: > > > > > > ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.24-rc6/2.6.24-rc6-mm1/ > > [snip] > > > +md-support-external-metadata-for-md-arrays.patch > > > +md-give-userspace-control-over-removing-failed-devices-when-external-metdata-in-use.patch > > > +md-allow-a-maximum-extent-to-be-set-for-resyncing.patch > > > +md-allow-devices-to-be-shared-between-md-arrays.patch > > > +md-lock-address-when-changing-attributes-of-component-devices.patch > > > +md-allow-an-md-array-to-appear-with-0-drives-if-it-has-external-metadata.patch > > > > > > RAID updates > > Should I blame the raid1 changes or the kobject changes? > > > > I don't know. It could even be that both patch series are OK but when they > are combined, things fail.
OK, I debugged this some more. It looks like two bugs meshed together.
One new bug: "do_md_run() returned -22" I can't seem to start my raid anymore. The following part of md-allow-devices-to-be-shared-between-md-arrays adds a new check to do_md_run() (drivers/md/md.c) that fails for my system: @@ -3213,8 +3283,11 @@ static int do_md_run(mddev_t * mddev) /* * Analyze all RAID superblock(s) */ - if (!mddev->raid_disks) + if (!mddev->raid_disks) { + if (!mddev->persistent) + return -EINVAL; analyze_sbs(mddev); + }
chunk_size = mddev->chunk_size;
The raid gets started normally with any other kernel I tried. I did not investigate the cause of this failure further, because I was looking why a failure to start a raid was causing event/3 to oops.
This looks like a secound, but rather old bug. do_md_stop (from drivers/md/md.c) does the following: 3691 /* make sure all delayed_delete calls have finished */ 3692 flush_scheduled_work(); 3693 3694 export_array(mddev); 3695 But: Only the callchain export_array -> kick_rdev_from_array -> unbind_rdev_from_array schedules the delayed_delete's!
After adding a second flush_scheduled_work() below the export_array() the resulting kernel no longer oopses and my initrd normally asks for an alternative root-fs, because of the first bug the raid still does not get started.
I don't know if this flush_scheduled_work() is misplaced since is was introduced, or if it really even was only trying to flush delayed deletes from previously stopped arrays.
When investigation this, I got these debug-outputs: first try, with my second flush_scheduled_work removed again: [ 34.290576] md: Autodetecting RAID arrays. [ 34.125649] md: Scanned 5 and added 5 devices. [ 34.125649] md: autorun ... [ 34.125649] md: considering sdc2 ... [ 34.125658] md: adding sdc2 ... [ 34.126914] md: adding sdb2 ... [ 34.128170] md: sdb1 has different UUID to sdc2 [ 34.135654] md: adding sda2 ... [ 34.137168] md: sda1 has different UUID to sdc2 [ 34.145669] md: created md1 [ 34.146755] md: bind<sda2> [ 34.147879] md: bind<sdb2> [ 34.155665] md: bind<sdc2> [ 34.156730] md: running: <sdc2><sdb2><sda2> [ 34.158427] mddev not persistent ??? [ 34.165651] md: do_md_run() returned -22 [ 34.167171] md: md1 stopped. [ 34.168292] 1:flush_scheduled_work() -> this is the original flush_scheduled_work()-call [ 34.175675] md: unbind<sdc2> [ 34.176795] md: remove sysfs-link 'block', schedule delayed_delete... following output is from unbind_rdev_from_array: [ 34.185662] XXX:unb:rdev == ffff81011ede4800 <3>XXX:unb:rdev->bdev == ffff81011f86b600 <3>XXX:unb:rdev->kobj == ffff81011ede4860 <6>md: export_rdev(sdc2) [ 34.196600] md: unbind<sdb2> [ 34.197720] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.205654] XXX:unb:rdev == ffff81011ede4600 <3>XXX:unb:rdev->bdev == ffff81011f86b080 <3>XXX:unb:rdev->kobj == ffff81011ede4660 <6>md: export_rdev(sdb2) [ 34.217942] md: unbind<sda2> [ 34.225651] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.228140] XXX:unb:rdev == ffff81011ede4400 <3>XXX:unb:rdev->bdev == ffff81011f86a000 <3>XXX:unb:rdev->kobj == ffff81011ede4460 <6>md: export_rdev(sda2) [ 34.245664] 2:!flush_scheduled_work() -> my second call is disabled for this run [ 34.247101] md: considering sdb1 ... [ 34.248492] md: adding sdb1 ... [ 34.255654] md: adding sda1 ... following output is from delayed_delete: [ 34.257024] XXX:dd:rdev == ffff81011ede4800 <3>XXX:dd:rdev->kobj == ffff81011ede4860 -> sdc2 seems to get deleted normally <3>XXX:dd:rdev == ffff81011ede4600 <3>XXX:dd:rdev->kobj == ffff81011ede4660 -> sdb2 too <3>XXX:dd:rdev == ffff81011ede4400 <3>XXX:dd:rdev->bdev == 5441505645440064 -> but here is something strange, the other devices did not get a bdev-line, because that value was zero <6>md: created md0 [ 34.654554] md: bind<sda1> [ 34.654554] md: bind<sdb1> [ 34.654554] md: running: <sdb1><sda1> [ 34.654554] mddev not persistent ??? [ 34.654554] md: do_md_run() returned -22 [ 34.654554] md: md0 stopped. [ 34.654554] 1:flush_scheduled_work() -> the flush from the second failed raid forces the delayed_deletes from the first raid to finish [ 34.285652] XXX:dd:rdev->kobj == ffff81011ede4460 -> the pointer itself looks still the same, but the kobject seems to be gone: <1>Unable to handle kernel paging request at 0000000034333545 RIP: [ 34.288794] [<ffffffff803b49a1>] kref_put+0x31/0x80 [ 34.291688] PGD 7e427067 PUD 7ed22067 PMD 0 [ 34.293394] Oops: 0002 [1] SMP [ 34.294651] last sysfs file: /sys/devices/virtual/block/md0/dev [ 34.295649] CPU 3 [ 34.295649] Modules linked in: [ 34.295649] Pid: 18, comm: events/3 Not tainted 2.6.24-rc6-mm1 #9 [ 34.295649] RIP: 0010:[<ffffffff803b49a1>] [<ffffffff803b49a1>] kref_put+0x31/0x80 [ 34.295649] RSP: 0000:ffff81007ffe5df0 EFLAGS: 00010202 [ 34.295649] RAX: 0000000000000000 RBX: 0000000034333545 RCX: ffffffff80606270 [ 34.295649] RDX: 0000000000000040 RSI: ffffffff803b38b0 RDI: 0000000034333545 [ 34.295649] RBP: ffff81007ffe5e00 R08: 0000000000000001 R09: 0000000000000000 [ 34.295649] R10: ffffffff8094c430 R11: 0000000000000000 R12: ffffffff803b38b0 [ 34.295650] R13: ffff81011ede44d8 R14: ffffffff804d7d50 R15: ffff81011ff210f0 [ 34.295650] FS: 0000000002024870(0000) GS:ffff81011ff0dd00(0000) knlGS:0000000000000000 [ 34.295650] CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b [ 34.295650] CR2: 0000000034333545 CR3: 000000007e535000 CR4: 00000000000006e0 [ 34.295650] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 34.295650] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 34.295650] Process events/3 (pid: 18, threadinfo ffff81007ffe4000, task ffff81007ffe2000) [ 34.295650] Stack: ffff81011ede4460 ffff81011ede4400 ffff81007ffe5e10 ffffffff803b37e9 [ 34.295650] ffff81007ffe5e30 ffffffff803b389b ffffffff804d7d50 ffff81011ede4460 [ 34.295650] ffff81007ffe5e50 ffffffff804d7db9 ffff81011ede44e0 ffff81011ff210c0 [ 34.295650] Call Trace: [ 34.295650] [<ffffffff803b37e9>] kobject_put+0x19/0x20 [ 34.295650] [<ffffffff803b389b>] kobject_del+0x2b/0x40 [ 34.295650] [<ffffffff804d7d50>] delayed_delete+0x0/0xb0 [ 34.295650] [<ffffffff804d7db9>] delayed_delete+0x69/0xb0 [ 34.295650] [<ffffffff80249775>] run_workqueue+0x175/0x210 [ 34.295650] [<ffffffff8024a411>] worker_thread+0x71/0xb0 [ 34.295650] [<ffffffff8024d9e0>] autoremove_wake_function+0x0/0x40 [ 34.295650] [<ffffffff8024a3a0>] worker_thread+0x0/0xb0 [ 34.295650] [<ffffffff8024d5fd>] kthread+0x4d/0x80 [ 34.295650] [<ffffffff8020c4b8>] child_rip+0xa/0x12 [ 34.295650] [<ffffffff8020bbcf>] restore_args+0x0/0x30 [ 34.295650] [<ffffffff8024d5b0>] kthread+0x0/0x80 [ 34.295650] [<ffffffff8020c4ae>] child_rip+0x0/0x12 [ 34.295650] [ 34.295650] [ 34.295650] Code: f0 ff 0b 0f 94 c0 31 d2 84 c0 74 0b 48 89 df 41 ff d4 ba 01 [ 34.295650] RIP [<ffffffff803b49a1>] kref_put+0x31/0x80 [ 34.295650] RSP <ffff81007ffe5df0> [ 34.295650] CR2: 0000000034333545 [ 34.295653] ---[ end trace 60425fedd4d3ef22 ]--- Here the system hangs, the initrd does not prompt for an alternative root-fs
second try with the newly added flush: [ 34.267403] md: Autodetecting RAID arrays. [ 34.188217] md: Scanned 5 and added 5 devices. [ 34.188220] md: autorun ... [ 34.189306] md: considering sdc2 ... [ 34.190699] md: adding sdc2 ... [ 34.198224] md: adding sdb2 ... [ 34.199480] md: sdb1 has different UUID to sdc2 [ 34.201237] md: adding sda2 ... [ 34.208220] md: sda1 has different UUID to sdc2 [ 34.209993] md: created md1 [ 34.218220] md: bind<sda2> [ 34.219341] md: bind<sdb2> [ 34.220410] md: bind<sdc2> [ 34.221476] md: running: <sdc2><sdb2><sda2> [ 34.228963] mddev not persistent ??? [ 34.230350] md: do_md_run() returned -22 [ 34.238219] md: md1 stopped. [ 34.239339] 1:flush_scheduled_work() -> old call to flush_scheduled_work() [ 34.240749] md: unbind<sdc2> [ 34.248219] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.250716] XXX:unb:rdev == ffff81011ed6d800 <3>XXX:unb:rdev->bdev == ffff81011f86b600 <3>XXX:unb:rdev->kobj == ffff81011ed6d860 <6>md: export_rdev(sdc2) [ 34.268262] md: unbind<sdb2> [ 34.269382] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.278221] XXX:unb:rdev == ffff81011ed6de00 <3>XXX:unb:rdev->bdev == ffff81011f86b080 <3>XXX:unb:rdev->kobj == ffff81011ed6de60 <6>md: export_rdev(sdb2) [ 34.289123] md: unbind<sda2> [ 34.290244] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.298221] XXX:unb:rdev == ffff81011ed6da00 <3>XXX:unb:rdev->bdev == ffff81011f86a000 <3>XXX:unb:rdev->kobj == ffff81011ed6da60 <6>md: export_rdev(sda2) [ 34.310502] 2:flush_scheduled_work() -> newly added call to flush_scheduled_work() [ 34.318253] XXX:dd:rdev == ffff81011ed6d800 <3>XXX:dd:rdev->kobj == ffff81011ed6d860 <3>XXX:dd:rdev == ffff81011ed6de00 <3>XXX:dd:rdev->kobj == ffff81011ed6de60 -> this time, rdev->bdev/rdev->kobj from sda2 seem to be still ok. <3>XXX:dd:rdev == ffff81011ed6da00 <3>XXX:dd:rdev->kobj == ffff81011ed6da60 <6>md: considering sdb1 ... [ 34.339255] md: adding sdb1 ... [ 34.340511] md: adding sda1 ... [ 34.348520] md: created md0 [ 34.349608] md: bind<sda1> [ 34.350676] md: bind<sdb1> [ 34.351741] md: running: <sdb1><sda1> [ 34.358743] mddev not persistent ??? [ 34.360131] md: do_md_run() returned -22 -> same failure to start the second raid, but... [ 34.368219] md: md0 stopped. [ 34.369340] 1:flush_scheduled_work() -> ... this time the work is already done and no oops happend [ 34.370733] md: unbind<sdb1> [ 34.378219] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.380705] XXX:unb:rdev == ffff81011ed6dc00 <3>XXX:unb:rdev->bdev == ffff81011f86a580 <3>XXX:unb:rdev->kobj == ffff81011ed6dc60 <6>md: export_rdev(sdb1) [ 34.398254] md: unbind<sda1> [ 34.399373] md: remove sysfs-link 'block', schedule delayed_delete... [ 34.408221] XXX:unb:rdev == ffff81007ff51800 <3>XXX:unb:rdev->bdev == ffff81007f8a0580 <3>XXX:unb:rdev->kobj == ffff81007ff51860 <6>md: export_rdev(sda1) [ 34.419120] 2:flush_scheduled_work() [ 34.420510] XXX:dd:rdev == ffff81011ed6dc00 <3>XXX:dd:rdev->kobj == ffff81011ed6dc60 <3>XXX:dd:rdev == ffff81007ff51800 <3>XXX:dd:rdev->kobj == ffff81007ff51860 <6>md: ... autorun DONE. Here the system now asks for a root-fs as the normal root /dev/md1 was not started.
I hope these outputs help, if more are needed, just ask.
Torsten
| |