Re: Re[2]: RAID1 submirror failure causes reboot?
On Mon, Nov 13 2006, Neil Brown wrote: On Friday November 10, [EMAIL PROTECTED] wrote: Hello Neil, [87398.531579] blk: request botched NB NB That looks bad. Possible some bug in the IDE controller or elsewhere NB in the block layer. Jens: What might cause that? NB --snip-- NB That doesn't look like raid was involved. If it was you would expect NB to see raid1_end_write_request or raid1_end_read_request in that NB trace. So that might be the hard or soft part of IDE layer failing the system, or a PCI problem for example? What I think is happening here (and Jens: if you could tell me how impossible this is, that would be good) is this: Some error handling somewhere in the low-level ide driver is getting confused and somehow one the sector counts in the 'struct request' is getting set wrongly. blk_recalc_rq_sectors notices this and says blk: request botched. It tries to auto-correct by increasing rq-nr_sectors to be consistent with other counts. I'm *guessing* this is the wrong thing to do, and that it has a side-effect but bi_end_io is getting called on the Bi twice. The second time the bio has been freed and reused and the wrong b_end_io is called and it does the wrong thing. It doesn't sound at all unreasonable. It's most likely either a bug in the ide driver, or a bad bio being passed to the block layer (and later on to the request and driver). By bad I mean one that isn't entirely consistent, which could be a bug in eg md. The request botched error is usually a sign of something being severly screwed up. As you mention further down, get slab and page debugging enabled to potentially catch this earlier. It could be a sign of a freed bio or request with corrupt contents. This sounds a bit far-fetched, but it is the only explanation I can come up with for the observed back trace which is: [87403.706012] [c0103871] error_code+0x39/0x40 [87403.710794] [c0180e0a] mpage_end_io_read+0x5e/0x72 [87403.716154] [c0164af9] bio_endio+0x56/0x7b [87403.720798] [c0256778] __end_that_request_first+0x1e0/0x301 [87403.726985] [c02568a4] end_that_request_first+0xb/0xd [87403.732699] [c02bd73c] __ide_end_request+0x54/0xe1 [87403.738214] [c02bd807] ide_end_request+0x3e/0x5c [87403.743382] [c02c35df] task_error+0x5b/0x97 [87403.748113] [c02c36fa] task_in_intr+0x6e/0xa2 [87403.753120] [c02bf19e] ide_intr+0xaf/0x12c [87403.757815] [c013e5a7] handle_IRQ_event+0x23/0x57 [87403.763135] [c013e66f] __do_IRQ+0x94/0xfd [87403.767802] [c0105192] do_IRQ+0x32/0x68 [87403.772278] [c010372e] common_interrupt+0x1a/0x20 i.e. bio_endio goes straight to mpage_end_io despite the face that the filesystem is mounted over md/raid1. What is the workload? Is io to the real device mixed with io that came through md as well? Is the kernel compiled with CONFIG_DEBUG_SLAB=y and CONFIG_DEBUG_PAGEALLOC=y ?? They might help trigger the error earlier and so make the problem more obvious. Agree, that would be a good plan to enable. Other questions: are you seeing timeouts at any point? The ide timeout code has some request/bio resetting code which might be worrisome. NeilBrown -- Jens Axboe - To unsubscribe from this list: send the line unsubscribe linux-raid in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: Re[2]: RAID1 submirror failure causes reboot?
On Monday November 13, [EMAIL PROTECTED] wrote:
It doesn't sound at all unreasonable. It's most likely either a bug in
the ide driver, or a bad bio being passed to the block layer (and
later on to the request and driver). By bad I mean one that isn't
entirely consistent, which could be a bug in eg md.
I just noticed (while tracking raid6 problems...) that bio_clone calls
bio_phys_segments and bio_hw_segments (why does it do both?).
This calls blk_recount_segments which does calculations based on
-bi_bdev.
Only immediately after calling bio_clone, raid1 changes bi_bdev, thus
creating potential inconsistency in the bio. Would this sort of
inconsistency cause this problem?
Agree, that would be a good plan to enable. Other questions: are you
seeing timeouts at any point? The ide timeout code has some request/bio
resetting code which might be worrisome.
Jim could probably answer this with more authority, but there aren't
obvious timeouts from the logs he posted. A representative sample is:
[87338.675891] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87338.685143] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87338.694791] ide: failed opcode was: unknown
[87343.557424] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87343.566388] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87343.576105] ide: failed opcode was: unknown
[87348.472226] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87348.481170] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87348.490843] ide: failed opcode was: unknown
[87353.387028] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87353.395735] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87353.405500] ide: failed opcode was: unknown
[87353.461342] ide1: reset: success
Thanks,
NeilBrown
-
To unsubscribe from this list: send the line unsubscribe linux-raid in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: Re[2]: RAID1 submirror failure causes reboot?
On Tue, Nov 14 2006, Neil Brown wrote:
On Monday November 13, [EMAIL PROTECTED] wrote:
It doesn't sound at all unreasonable. It's most likely either a bug in
the ide driver, or a bad bio being passed to the block layer (and
later on to the request and driver). By bad I mean one that isn't
entirely consistent, which could be a bug in eg md.
I just noticed (while tracking raid6 problems...) that bio_clone calls
bio_phys_segments and bio_hw_segments (why does it do both?).
This calls blk_recount_segments which does calculations based on
-bi_bdev.
Only immediately after calling bio_clone, raid1 changes bi_bdev, thus
creating potential inconsistency in the bio. Would this sort of
inconsistency cause this problem?
raid1 should change it first, you are right. But it should not matter,
as the real device should have restrictions that are at least equal to
the md device. So it may be a bit more conservative, but I don't think
there's a problem bug there.
Agree, that would be a good plan to enable. Other questions: are you
seeing timeouts at any point? The ide timeout code has some request/bio
resetting code which might be worrisome.
Jim could probably answer this with more authority, but there aren't
obvious timeouts from the logs he posted. A representative sample is:
[87338.675891] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87338.685143] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87338.694791] ide: failed opcode was: unknown
[87343.557424] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87343.566388] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87343.576105] ide: failed opcode was: unknown
[87348.472226] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87348.481170] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87348.490843] ide: failed opcode was: unknown
[87353.387028] hdc: task_in_intr: status=0x59 { DriveReady SeekComplete
DataRequest Error }
[87353.395735] hdc: task_in_intr: error=0x01 { AddrMarkNotFound },
LBAsect=176315718, sector=176315711
[87353.405500] ide: failed opcode was: unknown
[87353.461342] ide1: reset: success
Then lets wait for Jim to repeat his testing with all the debugging
options enabled, that should make us a little wiser.
--
Jens Axboe
-
To unsubscribe from this list: send the line unsubscribe linux-raid in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: Re[2]: RAID1 submirror failure causes reboot?
On Friday November 10, [EMAIL PROTECTED] wrote: Hello Neil, [87398.531579] blk: request botched NB NB That looks bad. Possible some bug in the IDE controller or elsewhere NB in the block layer. Jens: What might cause that? NB --snip-- NB That doesn't look like raid was involved. If it was you would expect NB to see raid1_end_write_request or raid1_end_read_request in that NB trace. So that might be the hard or soft part of IDE layer failing the system, or a PCI problem for example? What I think is happening here (and Jens: if you could tell me how impossible this is, that would be good) is this: Some error handling somewhere in the low-level ide driver is getting confused and somehow one the sector counts in the 'struct request' is getting set wrongly. blk_recalc_rq_sectors notices this and says blk: request botched. It tries to auto-correct by increasing rq-nr_sectors to be consistent with other counts. I'm *guessing* this is the wrong thing to do, and that it has a side-effect but bi_end_io is getting called on the Bi twice. The second time the bio has been freed and reused and the wrong b_end_io is called and it does the wrong thing. This sounds a bit far-fetched, but it is the only explanation I can come up with for the observed back trace which is: [87403.706012] [c0103871] error_code+0x39/0x40 [87403.710794] [c0180e0a] mpage_end_io_read+0x5e/0x72 [87403.716154] [c0164af9] bio_endio+0x56/0x7b [87403.720798] [c0256778] __end_that_request_first+0x1e0/0x301 [87403.726985] [c02568a4] end_that_request_first+0xb/0xd [87403.732699] [c02bd73c] __ide_end_request+0x54/0xe1 [87403.738214] [c02bd807] ide_end_request+0x3e/0x5c [87403.743382] [c02c35df] task_error+0x5b/0x97 [87403.748113] [c02c36fa] task_in_intr+0x6e/0xa2 [87403.753120] [c02bf19e] ide_intr+0xaf/0x12c [87403.757815] [c013e5a7] handle_IRQ_event+0x23/0x57 [87403.763135] [c013e66f] __do_IRQ+0x94/0xfd [87403.767802] [c0105192] do_IRQ+0x32/0x68 [87403.772278] [c010372e] common_interrupt+0x1a/0x20 i.e. bio_endio goes straight to mpage_end_io despite the face that the filesystem is mounted over md/raid1. Is the kernel compiled with CONFIG_DEBUG_SLAB=y and CONFIG_DEBUG_PAGEALLOC=y ?? They might help trigger the error earlier and so make the problem more obvious. NeilBrown - To unsubscribe from this list: send the line unsubscribe linux-raid in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
Re[2]: RAID1 submirror failure causes reboot?
Hello Neil, [87398.531579] blk: request botched NB NB That looks bad. Possible some bug in the IDE controller or elsewhere NB in the block layer. Jens: What might cause that? NB --snip-- NB That doesn't look like raid was involved. If it was you would expect NB to see raid1_end_write_request or raid1_end_read_request in that NB trace. So that might be the hard or soft part of IDE layer failing the system, or a PCI problem for example? Just in case, motherboard is Supermicro X5DPE-G2: e7501 chipset, Dual Xeon-533. Rather old now, way cool back when it was bought ;) But, as anything new, it could be manufactured bad. Maybe now there are some well-known problems with the tech? NB Do you have any other partitions of hdc in use but not on raid? NB Which partition is sector 176315718 in ?? All partitions are mirrored, and this sector is in hdc11: # fdisk /dev/hdc ... Command (m for help): u Changing display/entry units to sectors Command (m for help): p Disk /dev/hdc: 102.9 GB, 102935347200 bytes 16 heads, 63 sectors/track, 199450 cylinders, total 201045600 sectors Units = sectors of 1 * 512 = 512 bytes Device Boot Start End Blocks Id System /dev/hdc1 * 63 1000943 500440+ fd Linux raid autodetect /dev/hdc2 1000944 5001695 2000376 fd Linux raid autodetect /dev/hdc3 500169616721711 5860008 83 Linux /dev/hdc416721712 201045599921619445 Extended /dev/hdc51672177524534719 3906472+ 83 Linux /dev/hdc62453478328441727 1953472+ 83 Linux /dev/hdc72844179132348735 1953472+ 83 Linux /dev/hdc83234879944068751 5859976+ 83 Linux /dev/hdc94406881551881759 3906472+ 83 Linux /dev/hdc10 5188182359694767 3906472+ 83 Linux /dev/hdc11 59694831 19055534365430256+ 83 Linux /dev/hdc12 190555407 201045599 5245096+ 83 Linux -- Best regards, Jim Klimovmailto:[EMAIL PROTECTED] - To unsubscribe from this list: send the line unsubscribe linux-raid in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
