MD bug or me being stupid?

MD bug or me being stupid?

[Molle Bestefich]

Just upgraded a MD RAID 5 box to 2.6.11 from 2.4.something.

Found out one disk was failing completely, got a replacement from Maxtor.  Neat.
Replaced disk, rebooted..
Added the new disk to the array with 'raidhotadd'.
MD started syncing.

A couple of minutes into the process, it started *seriously* spamming
the console with messages:

==========================
Apr 22 01:47:00 linux kernel: ..<6>md: syncing RAID array md1
Apr 22 01:47:00 linux kernel: md: minimum _guaranteed_ reconstruction
speed: 1000 KB/sec/disc.
Apr 22 01:47:00 linux kernel: md: using maximum available idle IO bandwith (but
not more than 200000 KB/sec) for reconstruction.
Apr 22 01:47:00 linux kernel: md: using 128k window, over a total of
199141632 blocks.
Apr 22 01:47:00 linux kernel: md: md1: sync done.
Apr 22 01:47:00 linux kernel: ..<6>md: syncing RAID array md1
Apr 22 01:47:01 linux kernel: md: minimum _guaranteed_ reconstruction
speed: 1000 KB/sec/disc.
Apr 22 01:47:01 linux kernel: md: using maximum available idle IO bandwith (but
not more than 200000 KB/sec) for reconstruction.
Apr 22 01:47:01 linux kernel: md: using 128k window, over a total of
199141632 blocks.
Apr 22 01:47:01 linux kernel: md: md1: sync done.
==========================

Thought it had probably gone haywire and decided to start trashing my
data, so pulled the plug and rebooted.  When examining the log
afterwards, I can see that the above messages repeat themselves.
cat /var/log/messages | grep md | grep 'Apr 22 01:47:01' | grep 'sync done'
tells me that the messages were repeated 12 times per second.  The
/var/log/messages file grew to 600kB before I pulled the plug.

Noticed something strange during next boot: Linux failed to recognize
one of the disks.  Booted into Maxtor PowerMax and it said various
weird things (seemed different each time) about the disk too.  So
decided to switch ATA cables on this disk, which made wonders - both
PowerMax and Linux talks to the disk fine now.

Now, when I boot the machine, the 6 disks in the array have these
event counters, according to mdadm:

sda1:  0.19704  (completely new, "blank" disk)
sdb1:  0.19704
sdc1:  0.144      (but why?)
sdd1:  0.19704
sde1:  0.19704  (this disk had the bad cable)
sdf1:  0.19704

My questions now are (and yes, I know I had faulty hardware, but
that's incidentally also the reason I use MD at all):

1. What's with the infinitely repeated md1: sync done messages?

2. Wouldn't the mentioned event counters cause MD to think that the
totally blank disk /dev/sda1 has valid data, and that the disk with
valid data (/dev/sdc1) does not next time it syncs?

3. How do I proceed from here, if I want to rescue my data?


Best regards, many thanks for MD and all that :-).

Re: MD bug or me being stupid?

[Molle Bestefich]

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

Hmm, I think the information in /var/log/messages are actually
interesting for MD debugging.

Seems there was a bad sector somewhere in the middle of all this,
which might have triggered something?

Attached (gzipped - sorry for the inconvenience, but it's 5 kB vs. 250 kB!)

I've cut out a lot of irrelevant cruft (kernel messages) and added
comments about what I did when.

[-- Attachment #2: linux-22apr-messages.gz --]
[-- Type: application/x-gzip, Size: 5713 bytes --]

Re: MD bug or me being stupid?

[Molle Bestefich]

On 4/22/05, Molle Bestefich wrote:
> Just upgraded a MD RAID 5 box to 2.6.11 from 2.4.something.
> 
> Found out one disk was failing completely, got a replacement from Maxtor.  Neat.
> Replaced disk, rebooted..
> Added the new disk to the array with 'raidhotadd'.
> MD started syncing.
> 
> A couple of minutes into the process, it started *seriously* spamming
> the console with messages:
> 
> ==========================
> Apr 22 01:47:00 linux kernel: ..<6>md: syncing RAID array md1
> Apr 22 01:47:00 linux kernel: md: minimum _guaranteed_ reconstruction
> speed: 1000 KB/sec/disc.
> Apr 22 01:47:00 linux kernel: md: using maximum available idle IO bandwith (but
> not more than 200000 KB/sec) for reconstruction.
> Apr 22 01:47:00 linux kernel: md: using 128k window, over a total of
> 199141632 blocks.
> Apr 22 01:47:00 linux kernel: md: md1: sync done.
> Apr 22 01:47:00 linux kernel: ..<6>md: syncing RAID array md1
> Apr 22 01:47:01 linux kernel: md: minimum _guaranteed_ reconstruction
> speed: 1000 KB/sec/disc.
> Apr 22 01:47:01 linux kernel: md: using maximum available idle IO bandwith (but
> not more than 200000 KB/sec) for reconstruction.
> Apr 22 01:47:01 linux kernel: md: using 128k window, over a total of
> 199141632 blocks.
> Apr 22 01:47:01 linux kernel: md: md1: sync done.
> ==========================

[snip]

> afterwards, I can see that the above messages repeat themselves.
> cat /var/log/messages | grep md | grep 'Apr 22 01:47:01' | grep 'sync done'
> tells me that the messages were repeated 12 times per second.  The

Ping!...
Neil, just wondering, any comments regarding this particular endless loop in MD?
(Anything I can test or some such?)

Re: MD bug or me being stupid?

[Neil Brown]

On Thursday May 12, molle.bestefich@gmail.com wrote:
> On 4/22/05, Molle Bestefich wrote:
> > Just upgraded a MD RAID 5 box to 2.6.11 from 2.4.something.
> > 
> > Found out one disk was failing completely, got a replacement from Maxtor.  Neat.
> > Replaced disk, rebooted..
> > Added the new disk to the array with 'raidhotadd'.
> > MD started syncing.
> > 
> > A couple of minutes into the process, it started *seriously* spamming
> > the console with messages:
> > 
> > ==========================
> > Apr 22 01:47:00 linux kernel: ..<6>md: syncing RAID array md1
> > Apr 22 01:47:00 linux kernel: md: minimum _guaranteed_ reconstruction
> > speed: 1000 KB/sec/disc.
> > Apr 22 01:47:00 linux kernel: md: using maximum available idle IO bandwith (but
> > not more than 200000 KB/sec) for reconstruction.
> > Apr 22 01:47:00 linux kernel: md: using 128k window, over a total of
> > 199141632 blocks.
> > Apr 22 01:47:00 linux kernel: md: md1: sync done.
> > Apr 22 01:47:00 linux kernel: ..<6>md: syncing RAID array md1
> > Apr 22 01:47:01 linux kernel: md: minimum _guaranteed_ reconstruction
> > speed: 1000 KB/sec/disc.
> > Apr 22 01:47:01 linux kernel: md: using maximum available idle IO bandwith (but
> > not more than 200000 KB/sec) for reconstruction.
> > Apr 22 01:47:01 linux kernel: md: using 128k window, over a total of
> > 199141632 blocks.
> > Apr 22 01:47:01 linux kernel: md: md1: sync done.
> > ==========================
> 
> [snip]
> 
> > afterwards, I can see that the above messages repeat themselves.
> > cat /var/log/messages | grep md | grep 'Apr 22 01:47:01' | grep 'sync done'
> > tells me that the messages were repeated 12 times per second.  The
> 
> Ping!...
> Neil, just wondering, any comments regarding this particular endless loop in MD?
> (Anything I can test or some such?)

Thanks for the ping, things sometimes get lost in the noise....

This sounds a bit like the problem that is addressed by 
  md-make-raid5-and-raid6-robust-against-failure-during-recovery.patch 
in the current -mm patches (look in the brokenout directory).

This would only happen if you have multiple failed devices.  So maybe
while the rebuild was happening, another device failed (which seems to
happen more and more as device sizes are increasing and reliability is
going the other way).

Could this (another drive failure) be the case?

NeilBrown

Re: MD bug or me being stupid?

[Molle Bestefich]

Neil Brown wrote:
> Molle Bestefich wrote:
> > Ping!...
> > Neil, just wondering, any comments regarding this particular endless loop in MD?
> > (Anything I can test or some such?)
> 
> Thanks for the ping, things sometimes get lost in the noise....

Thanks for taking a look at it!

> This sounds a bit like the problem that is addressed by
>   md-make-raid5-and-raid6-robust-against-failure-during-recovery.patch
> in the current -mm patches (look in the brokenout directory).
> 
> This would only happen if you have multiple failed devices.  So maybe
> while the rebuild was happening, another device failed (which seems to
> happen more and more as device sizes are increasing and reliability is
> going the other way).
> 
> Could this (another drive failure) be the case?

Sounds correct!
There was both a real disk failure and a cable failure involved (first
message in this thread has details).

Apologies for bringing up already fixed bugs.

Strange behaviour on "toy array"

[Patrik Jonsson]

hi all,

I'm gearing up to setting up a 2tb raid for our research group, and just 
to see how this stuff works I made a loopback array on one of my 
machines. I created 5 loopback devices of 1mb each, created a raid5 
array and formatted. so far so good. I could copy files on and off, fail 
a disk with mdadm -f  and then return it and everything seemed to work 
as i expected. Then I decided to see what happens if things go bad, so i 
fail one disk. fine, array reports "clean, degraded" but I can still 
access files. Then I fail another, now expecting not to be able to read 
anything. But, array reports "clean, degraded" and I can still access 
the files. I then proceeded to fail ALL disks and the array was still 
"clean, degraded" and I could read the files on it just as well as 
before??? Can anyone explain to me what's going on here? Was I seeing 
some cached version (given that the array was so small)?

This is on a machine running fedora core 3 ppc.

thanks,

/Patrik

Re: Strange behaviour on "toy array"

[David Greaves]

Patrik Jonsson wrote:

> hi all,
>
> I'm gearing up to setting up a 2tb raid for our research group, and
> just to see how this stuff works I made a loopback array on one of my
> machines. I created 5 loopback devices of 1mb each, created a raid5
> array and formatted. so far so good. I could copy files on and off,
> fail a disk with mdadm -f  and then return it and everything seemed to
> work as i expected. Then I decided to see what happens if things go
> bad, so i fail one disk. fine, array reports "clean, degraded" but I
> can still access files. Then I fail another, now expecting not to be
> able to read anything. But, array reports "clean, degraded" and I can
> still access the files. I then proceeded to fail ALL disks and the
> array was still "clean, degraded" and I could read the files on it
> just as well as before??? Can anyone explain to me what's going on
> here? Was I seeing some cached version (given that the array was so
> small)?

I think you'd need to post the commands you used and the results of 
things like mdadm --detail and cat /proc/mdstat
also kernel version, mdadm version etc.

That way we can ensure you really did fail the right drives etc etc.

Right now it could be anything from (allowed!) user error to a weird ppc
thing...

FYI I run a 1.2Tb array on 6x250Gb SATA drives (1 spare) with lvm2 and xfs

David

Re: Strange behaviour on "toy array"

[Patrik Jonsson]

David Greaves wrote:

>
>I think you'd need to post the commands you used and the results of 
>things like mdadm --detail and cat /proc/mdstat
>also kernel version, mdadm version etc.
>
>That way we can ensure you really did fail the right drives etc etc.
>
>Right now it could be anything from (allowed!) user error to a weird ppc
>thing...
>  
>
sure thing:
[root@localhost junk]# uname -a
Linux localhost.localdomain 2.6.9-prep #1 Tue Apr 19 16:00:33 PDT 2005 
ppc ppc ppc GNU/Linux
[root@localhost junk]# mdadm --version
mdadm - v1.6.0 - 4 June 2004

now I do (loop1-5 are files):
losetup /dev/loop0 loop1
losetup /dev/loop1 loop2
losetup /dev/loop2 loop3
losetup /dev/loop3 loop4
losetup /dev/loop4 loop5
mdadm --create /dev/md0 -l 5 -n 5 /dev/loop0 /dev/loop1 /dev/loop2 
/dev/loop3 /dev/loop4
mkfs.ext3 /dev/md0
mount -t ext3 /dev/md0 junk

at this point, mdadm shows:
[root@localhost junk]# mdadm --detail /dev/md0
/dev/md0:
        Version : 00.90.01
  Creation Time : Sun May 15 13:41:24 2005
     Raid Level : raid5
     Array Size : 3840
    Device Size : 960
   Raid Devices : 5
  Total Devices : 5
Preferred Minor : 0
    Persistence : Superblock is persistent

    Update Time : Sun May 15 13:45:34 2005
          State : clean
 Active Devices : 5
Working Devices : 5
 Failed Devices : 0
  Spare Devices : 0

         Layout : left-symmetric
     Chunk Size : 64K

    Number   Major   Minor   RaidDevice State
       0       7        0        0      active sync   /dev/loop0
       1       7        1        1      active sync   /dev/loop1
       2       7        2        2      active sync   /dev/loop2
       3       7        3        3      active sync   /dev/loop3
       4       7        4        4      active sync   /dev/loop4
           UUID : b89aa5de:da1054f5:b052cc51:393d7435
         Events : 0.24

and /proc/mdstat:
[root@localhost junk]# cat /proc/mdstat
Personalities : [raid5]
md0 : active raid5 loop4[4] loop3[3] loop2[2] loop1[1] loop0[0]
      3840 blocks level 5, 64k chunk, algorithm 2 [5/5] [UUUUU]
     
unused devices: <none>

Now I fail (e.g.) /dev/loop0:
mdadm -f /dev/md0 /dev/loop0

and get:
[root@localhost junk]# mdadm --detail /dev/md0
/dev/md0:
        Version : 00.90.01
  Creation Time : Sun May 15 13:41:24 2005
     Raid Level : raid5
     Array Size : 3840
    Device Size : 960
   Raid Devices : 5
  Total Devices : 5
Preferred Minor : 0
    Persistence : Superblock is persistent

    Update Time : Sun May 15 13:49:20 2005
          State : clean, degraded
 Active Devices : 4
Working Devices : 4
 Failed Devices : 1
  Spare Devices : 0

         Layout : left-symmetric
     Chunk Size : 64K

    Number   Major   Minor   RaidDevice State
       0       0        0       -1      removed
       1       7        1        1      active sync   /dev/loop1
       2       7        2        2      active sync   /dev/loop2
       3       7        3        3      active sync   /dev/loop3
       4       7        4        4      active sync   /dev/loop4
       5       7        0       -1      faulty   /dev/loop0
           UUID : b89aa5de:da1054f5:b052cc51:393d7435
         Events : 0.27

and:
[root@localhost junk]# cat /proc/mdstat
Personalities : [raid5]
md0 : active raid5 loop4[4] loop3[3] loop2[2] loop1[1] loop0[5](F)
      3840 blocks level 5, 64k chunk, algorithm 2 [5/4] [_UUUU]
     
unused devices: <none>

continue failing drives:
[root@localhost junk]# mdadm -f /dev/md0 /dev/loop1
mdadm: set /dev/loop1 faulty in /dev/md0
[root@localhost junk]# mdadm -f /dev/md0 /dev/loop2
mdadm: set /dev/loop2 faulty in /dev/md0
[root@localhost junk]# mdadm -f /dev/md0 /dev/loop3
mdadm: set /dev/loop3 faulty in /dev/md0
[root@localhost junk]# mdadm -f /dev/md0 /dev/loop4
mdadm: set /dev/loop4 faulty in /dev/md0

now I get:
[root@localhost junk]# mdadm --detail /dev/md0
/dev/md0:
        Version : 00.90.01
  Creation Time : Sun May 15 13:41:24 2005
     Raid Level : raid5
     Array Size : 3840
    Device Size : 960
   Raid Devices : 5
  Total Devices : 5
Preferred Minor : 0
    Persistence : Superblock is persistent

    Update Time : Sun May 15 13:51:09 2005
          State : clean, degraded
 Active Devices : 0
Working Devices : 0
 Failed Devices : 5
  Spare Devices : 0

         Layout : left-symmetric
     Chunk Size : 64K

    Number   Major   Minor   RaidDevice State
       0       0        0       -1      removed
       1       0        0       -1      removed
       2       0        0       -1      removed
       3       0        0       -1      removed
       4       0        0       -1      removed
       5       7        4       -1      faulty   /dev/loop4
       6       7        3       -1      faulty   /dev/loop3
       7       7        2       -1      faulty   /dev/loop2
       8       7        1       -1      faulty   /dev/loop1
       9       7        0       -1      faulty   /dev/loop0

and:
Personalities : [raid5]
md0 : active raid5 loop4[5](F) loop3[6](F) loop2[7](F) loop1[8](F) 
loop0[9](F)
      3840 blocks level 5, 64k chunk, algorithm 2 [5/0] [_____]
     
unused devices: <none>

but I can still read the file on the filesystem that is mounted (ie in 
the "junk" dir).

Hope that contains all the info you need.

/Patrik

RE: Strange behaviour on "toy array"

[Guy]

Ok, now put more files on your filesystem.

I think you are correct and the buffer cache is handling the reads.

> -----Original Message-----
> From: linux-raid-owner@vger.kernel.org [mailto:linux-raid-
> owner@vger.kernel.org] On Behalf Of Patrik Jonsson
> Sent: Sunday, May 15, 2005 4:55 PM
> To: David Greaves; linux-raid@vger.kernel.org
> Subject: Re: Strange behaviour on "toy array"
> 
> 
> 
> David Greaves wrote:
> 
> >
> >I think you'd need to post the commands you used and the results of
> >things like mdadm --detail and cat /proc/mdstat
> >also kernel version, mdadm version etc.
> >
> >That way we can ensure you really did fail the right drives etc etc.
> >
> >Right now it could be anything from (allowed!) user error to a weird ppc
> >thing...
> >
> >
> sure thing:
> [root@localhost junk]# uname -a
> Linux localhost.localdomain 2.6.9-prep #1 Tue Apr 19 16:00:33 PDT 2005
> ppc ppc ppc GNU/Linux
> [root@localhost junk]# mdadm --version
> mdadm - v1.6.0 - 4 June 2004
> 
> now I do (loop1-5 are files):
> losetup /dev/loop0 loop1
> losetup /dev/loop1 loop2
> losetup /dev/loop2 loop3
> losetup /dev/loop3 loop4
> losetup /dev/loop4 loop5
> mdadm --create /dev/md0 -l 5 -n 5 /dev/loop0 /dev/loop1 /dev/loop2
> /dev/loop3 /dev/loop4
> mkfs.ext3 /dev/md0
> mount -t ext3 /dev/md0 junk
> 
> at this point, mdadm shows:
> [root@localhost junk]# mdadm --detail /dev/md0
> /dev/md0:
>         Version : 00.90.01
>   Creation Time : Sun May 15 13:41:24 2005
>      Raid Level : raid5
>      Array Size : 3840
>     Device Size : 960
>    Raid Devices : 5
>   Total Devices : 5
> Preferred Minor : 0
>     Persistence : Superblock is persistent
> 
>     Update Time : Sun May 15 13:45:34 2005
>           State : clean
>  Active Devices : 5
> Working Devices : 5
>  Failed Devices : 0
>   Spare Devices : 0
> 
>          Layout : left-symmetric
>      Chunk Size : 64K
> 
>     Number   Major   Minor   RaidDevice State
>        0       7        0        0      active sync   /dev/loop0
>        1       7        1        1      active sync   /dev/loop1
>        2       7        2        2      active sync   /dev/loop2
>        3       7        3        3      active sync   /dev/loop3
>        4       7        4        4      active sync   /dev/loop4
>            UUID : b89aa5de:da1054f5:b052cc51:393d7435
>          Events : 0.24
> 
> and /proc/mdstat:
> [root@localhost junk]# cat /proc/mdstat
> Personalities : [raid5]
> md0 : active raid5 loop4[4] loop3[3] loop2[2] loop1[1] loop0[0]
>       3840 blocks level 5, 64k chunk, algorithm 2 [5/5] [UUUUU]
> 
> unused devices: <none>
> 
> Now I fail (e.g.) /dev/loop0:
> mdadm -f /dev/md0 /dev/loop0
> 
> and get:
> [root@localhost junk]# mdadm --detail /dev/md0
> /dev/md0:
>         Version : 00.90.01
>   Creation Time : Sun May 15 13:41:24 2005
>      Raid Level : raid5
>      Array Size : 3840
>     Device Size : 960
>    Raid Devices : 5
>   Total Devices : 5
> Preferred Minor : 0
>     Persistence : Superblock is persistent
> 
>     Update Time : Sun May 15 13:49:20 2005
>           State : clean, degraded
>  Active Devices : 4
> Working Devices : 4
>  Failed Devices : 1
>   Spare Devices : 0
> 
>          Layout : left-symmetric
>      Chunk Size : 64K
> 
>     Number   Major   Minor   RaidDevice State
>        0       0        0       -1      removed
>        1       7        1        1      active sync   /dev/loop1
>        2       7        2        2      active sync   /dev/loop2
>        3       7        3        3      active sync   /dev/loop3
>        4       7        4        4      active sync   /dev/loop4
>        5       7        0       -1      faulty   /dev/loop0
>            UUID : b89aa5de:da1054f5:b052cc51:393d7435
>          Events : 0.27
> 
> and:
> [root@localhost junk]# cat /proc/mdstat
> Personalities : [raid5]
> md0 : active raid5 loop4[4] loop3[3] loop2[2] loop1[1] loop0[5](F)
>       3840 blocks level 5, 64k chunk, algorithm 2 [5/4] [_UUUU]
> 
> unused devices: <none>
> 
> continue failing drives:
> [root@localhost junk]# mdadm -f /dev/md0 /dev/loop1
> mdadm: set /dev/loop1 faulty in /dev/md0
> [root@localhost junk]# mdadm -f /dev/md0 /dev/loop2
> mdadm: set /dev/loop2 faulty in /dev/md0
> [root@localhost junk]# mdadm -f /dev/md0 /dev/loop3
> mdadm: set /dev/loop3 faulty in /dev/md0
> [root@localhost junk]# mdadm -f /dev/md0 /dev/loop4
> mdadm: set /dev/loop4 faulty in /dev/md0
> 
> now I get:
> [root@localhost junk]# mdadm --detail /dev/md0
> /dev/md0:
>         Version : 00.90.01
>   Creation Time : Sun May 15 13:41:24 2005
>      Raid Level : raid5
>      Array Size : 3840
>     Device Size : 960
>    Raid Devices : 5
>   Total Devices : 5
> Preferred Minor : 0
>     Persistence : Superblock is persistent
> 
>     Update Time : Sun May 15 13:51:09 2005
>           State : clean, degraded
>  Active Devices : 0
> Working Devices : 0
>  Failed Devices : 5
>   Spare Devices : 0
> 
>          Layout : left-symmetric
>      Chunk Size : 64K
> 
>     Number   Major   Minor   RaidDevice State
>        0       0        0       -1      removed
>        1       0        0       -1      removed
>        2       0        0       -1      removed
>        3       0        0       -1      removed
>        4       0        0       -1      removed
>        5       7        4       -1      faulty   /dev/loop4
>        6       7        3       -1      faulty   /dev/loop3
>        7       7        2       -1      faulty   /dev/loop2
>        8       7        1       -1      faulty   /dev/loop1
>        9       7        0       -1      faulty   /dev/loop0
> 
> and:
> Personalities : [raid5]
> md0 : active raid5 loop4[5](F) loop3[6](F) loop2[7](F) loop1[8](F)
> loop0[9](F)
>       3840 blocks level 5, 64k chunk, algorithm 2 [5/0] [_____]
> 
> unused devices: <none>
> 
> but I can still read the file on the filesystem that is mounted (ie in
> the "junk" dir).
> 
> Hope that contains all the info you need.
> 
> /Patrik
> 
> -
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html