Rebuild events while scrubbing - problems or just informational?

Rebuild events while scrubbing - problems or just informational?

[Mark Knecht]

Hi,
   A few weeks back I set up cron to do a weekly scrub on my home
machine. I've since noticed these rebuild event messages in the logs
for each scrub that's occurred so far. Are they just part of the
normal process of mdadm doing it's work or are they pointing to some
sort of problem I'm not yet recognizing? I found it interesting that
they were all almost exactly 33 minutes, 20 seconds apart. Are the 5
messages related to the 5 drives in my RAID6?

   I found numerous others who have seen this over the years and say
it's not indicative of any problem but did recommend running smartctl
so I've done smartctl -t long tests on all the drives and didn't see
anything special getting reported. All tests completed without errors
so I'm hoping these messages just part of the normal reporting but
don't remember seeing them in the past. Note that for a long time (a
year maybe?) I completely forgot about scrubbing so there is a big gap
in my memory here.

   I'm running a more or less stable Gentoo amd64 box. The kernel is
3.10.22 and mdadm is version 3.2.6-r1 which is the latest stable
version in portage.

Thanks in advance,
Mark

c2RAID6 log # cat /proc/mdstat
Personalities : [linear] [raid0] [raid1] [raid10] [raid6] [raid5] [raid4]
md3 : active raid6 sdb3[9] sdf3[5] sde3[6] sdd3[7] sdc3[8]
      1452264480 blocks super 1.2 level 6, 16k chunk, algorithm 2 [5/5] [UUUUU]

unused devices: <none>
c2RAID6 log #


Dec  8 14:30:01 c2RAID6 kernel: [29557.910269] md: data-check of RAID array md3
Dec  8 14:30:01 c2RAID6 kernel: [29557.910272] md: minimum
_guaranteed_  speed: 1000 KB/sec/disk.
Dec  8 14:30:01 c2RAID6 kernel: [29557.910274] md: using maximum
available idle IO bandwidth (but not more than 200000 KB/sec) for
data-check.
Dec  8 14:30:01 c2RAID6 kernel: [29557.910278] md: using 128k window,
over a total of 484088160k.


Dec  8 14:30:01 c2RAID6 mdadm[1838]: RebuildStarted event detected on
md device /dev/md/3
Dec  8 15:03:21 c2RAID6 mdadm[1838]: Rebuild26 event detected on md
device /dev/md/3
Dec  8 15:36:41 c2RAID6 mdadm[1838]: Rebuild49 event detected on md
device /dev/md/3
Dec  8 16:10:01 c2RAID6 mdadm[1838]: Rebuild70 event detected on md
device /dev/md/3
Dec  8 16:43:21 c2RAID6 mdadm[1838]: Rebuild87 event detected on md
device /dev/md/3

Re: Rebuild events while scrubbing - problems or just informational?

[Robin Hill]

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

On Mon Dec 09, 2013 at 02:27:09PM -0800, Mark Knecht wrote:

> Hi,
>    A few weeks back I set up cron to do a weekly scrub on my home
> machine. I've since noticed these rebuild event messages in the logs
> for each scrub that's occurred so far. Are they just part of the
> normal process of mdadm doing it's work or are they pointing to some
> sort of problem I'm not yet recognizing? I found it interesting that
> they were all almost exactly 33 minutes, 20 seconds apart. Are the 5
> messages related to the 5 drives in my RAID6?
> 
>    I found numerous others who have seen this over the years and say
> it's not indicative of any problem but did recommend running smartctl
> so I've done smartctl -t long tests on all the drives and didn't see
> anything special getting reported. All tests completed without errors
> so I'm hoping these messages just part of the normal reporting but
> don't remember seeing them in the past. Note that for a long time (a
> year maybe?) I completely forgot about scrubbing so there is a big gap
> in my memory here.
> 
>    I'm running a more or less stable Gentoo amd64 box. The kernel is
> 3.10.22 and mdadm is version 3.2.6-r1 which is the latest stable
> version in portage.
> 
> Thanks in advance,
> Mark
> 
> c2RAID6 log # cat /proc/mdstat
> Personalities : [linear] [raid0] [raid1] [raid10] [raid6] [raid5] [raid4]
> md3 : active raid6 sdb3[9] sdf3[5] sde3[6] sdd3[7] sdc3[8]
>       1452264480 blocks super 1.2 level 6, 16k chunk, algorithm 2 [5/5] [UUUUU]
> 
> unused devices: <none>
> c2RAID6 log #
> 
> 
> Dec  8 14:30:01 c2RAID6 kernel: [29557.910269] md: data-check of RAID array md3
> Dec  8 14:30:01 c2RAID6 kernel: [29557.910272] md: minimum
> _guaranteed_  speed: 1000 KB/sec/disk.
> Dec  8 14:30:01 c2RAID6 kernel: [29557.910274] md: using maximum
> available idle IO bandwidth (but not more than 200000 KB/sec) for
> data-check.
> Dec  8 14:30:01 c2RAID6 kernel: [29557.910278] md: using 128k window,
> over a total of 484088160k.
> 
> 
> Dec  8 14:30:01 c2RAID6 mdadm[1838]: RebuildStarted event detected on
> md device /dev/md/3
> Dec  8 15:03:21 c2RAID6 mdadm[1838]: Rebuild26 event detected on md
> device /dev/md/3
> Dec  8 15:36:41 c2RAID6 mdadm[1838]: Rebuild49 event detected on md
> device /dev/md/3
> Dec  8 16:10:01 c2RAID6 mdadm[1838]: Rebuild70 event detected on md
> device /dev/md/3
> Dec  8 16:43:21 c2RAID6 mdadm[1838]: Rebuild87 event detected on md
> device /dev/md/3
> 

They're perfectly normal if you're doing a repair - I don't think they
should be there for a check though. It's just mdadm in monitor mode
reporting the progress (the numbers are the percentage completed) to
syslog.  According to the manual the default reporting interval is 20
percent, but I think it actually triggers on a completed stripe (or
block of stripes) so the numbers aren't exactly on the interval.

Cheers,
    Robin
-- 
     ___        
    ( ' }     |       Robin Hill        <robin@robinhill.me.uk> |
   / / )      | Little Jim says ....                            |
  // !!       |      "He fallen in de water !!"                 |

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]

Re: Rebuild events while scrubbing - problems or just informational?

[Can Jeuleers]

On 12/10/2013 09:52 AM, Robin Hill wrote:
>> Dec  8 14:30:01 c2RAID6 mdadm[1838]: RebuildStarted event detected on
>> md device /dev/md/3
>> Dec  8 15:03:21 c2RAID6 mdadm[1838]: Rebuild26 event detected on md
>> device /dev/md/3
>> Dec  8 15:36:41 c2RAID6 mdadm[1838]: Rebuild49 event detected on md
>> device /dev/md/3
>> Dec  8 16:10:01 c2RAID6 mdadm[1838]: Rebuild70 event detected on md
>> device /dev/md/3
>> Dec  8 16:43:21 c2RAID6 mdadm[1838]: Rebuild87 event detected on md
>> device /dev/md/3
>>
> 
> They're perfectly normal if you're doing a repair - I don't think they
> should be there for a check though. It's just mdadm in monitor mode
> reporting the progress (the numbers are the percentage completed) to
> syslog.  According to the manual the default reporting interval is 20
> percent, but I think it actually triggers on a completed stripe (or
> block of stripes) so the numbers aren't exactly on the interval.

I see them as well during checks. Although I can't find documentation
stating so I regard them as normal.

Re: Rebuild events while scrubbing - problems or just informational?

[NeilBrown]

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

On Tue, 10 Dec 2013 17:55:06 +0100 Can Jeuleers <can.jeuleers@gmail.com>
wrote:

> On 12/10/2013 09:52 AM, Robin Hill wrote:
> >> Dec  8 14:30:01 c2RAID6 mdadm[1838]: RebuildStarted event detected on
> >> md device /dev/md/3
> >> Dec  8 15:03:21 c2RAID6 mdadm[1838]: Rebuild26 event detected on md
> >> device /dev/md/3
> >> Dec  8 15:36:41 c2RAID6 mdadm[1838]: Rebuild49 event detected on md
> >> device /dev/md/3
> >> Dec  8 16:10:01 c2RAID6 mdadm[1838]: Rebuild70 event detected on md
> >> device /dev/md/3
> >> Dec  8 16:43:21 c2RAID6 mdadm[1838]: Rebuild87 event detected on md
> >> device /dev/md/3
> >>
> > 
> > They're perfectly normal if you're doing a repair - I don't think they
> > should be there for a check though. It's just mdadm in monitor mode
> > reporting the progress (the numbers are the percentage completed) to
> > syslog.  According to the manual the default reporting interval is 20
> > percent, but I think it actually triggers on a completed stripe (or
> > block of stripes) so the numbers aren't exactly on the interval.
> 
> I see them as well during checks. Although I can't find documentation
> stating so I regard them as normal.
> --

% man mdadm

Search for "RebuildStarted"

           RebuildStarted
                  An  md array started reconstruction. (syslog priority: Warn-
                  ing)


           RebuildNN
                  Where NN is a two-digit number (ie. 05, 48). This  indicates
                  that  rebuild has passed that many percent of the total. The
                  events are generated with fixed increment since 0. Increment
                  size  may be specified with a commandline option (default is
                  20). (syslog priority: Warning)



This is in a section which starts

MONITOR MODE
       Usage: mdadm --monitor options... devices...


       This usage causes mdadm to periodically poll a number of md arrays  and
       to report on any events noticed.  mdadm will never exit once it decides
       that there are arrays to be checked, so it should normally  be  run  in
       the background.


I guess that doesn't explicitly say it is normal, but that is the intent :-)

They should be generated from recovery, resync, reshape, check, repair and
anything else that might be added which processes the whole array like that.
I guess "Rebuild" isn't a very generic word.. but
   "StuffStarted"
   "Stuff20"
   "StuffFinished"
probably wouldn't go down well either.


Thanks,
NeilBrown


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: Rebuild events while scrubbing - problems or just informational?

[Can Jeuleers]

On 12/11/2013 02:38 AM, NeilBrown wrote:
> I guess that doesn't explicitly say it is normal, but that is the intent :-)
> 
> They should be generated from recovery, resync, reshape, check, repair and
> anything else that might be added which processes the whole array like that.
> I guess "Rebuild" isn't a very generic word.. but
>    "StuffStarted"
>    "Stuff20"
>    "StuffFinished"
> probably wouldn't go down well either.

Thanks Neil.

What I meant is that there is no definition of "reconstruction" in the
manpage, so that it is not formally clear whether check is or is not a
form of reconstruction.

I'll try and submit a manpage patch, but hopefully you'll accept it by
private email because I'm still banned from posting to any list hosted
by vger using my regular email accounts. My name is Jan Ceuleers, not
Can Jeuleers.

Jan

Re: Rebuild events while scrubbing - problems or just informational?

[Mark Knecht]

Thanks for the pointer Neil. Glad to know there isn't a problem here.

Cheers,
Mark

On Tue, Dec 10, 2013 at 5:38 PM, NeilBrown <neilb@suse.de> wrote:
> On Tue, 10 Dec 2013 17:55:06 +0100 Can Jeuleers <can.jeuleers@gmail.com>
> wrote:
>
>> On 12/10/2013 09:52 AM, Robin Hill wrote:
>> >> Dec  8 14:30:01 c2RAID6 mdadm[1838]: RebuildStarted event detected on
>> >> md device /dev/md/3
>> >> Dec  8 15:03:21 c2RAID6 mdadm[1838]: Rebuild26 event detected on md
>> >> device /dev/md/3
>> >> Dec  8 15:36:41 c2RAID6 mdadm[1838]: Rebuild49 event detected on md
>> >> device /dev/md/3
>> >> Dec  8 16:10:01 c2RAID6 mdadm[1838]: Rebuild70 event detected on md
>> >> device /dev/md/3
>> >> Dec  8 16:43:21 c2RAID6 mdadm[1838]: Rebuild87 event detected on md
>> >> device /dev/md/3
>> >>
>> >
>> > They're perfectly normal if you're doing a repair - I don't think they
>> > should be there for a check though. It's just mdadm in monitor mode
>> > reporting the progress (the numbers are the percentage completed) to
>> > syslog.  According to the manual the default reporting interval is 20
>> > percent, but I think it actually triggers on a completed stripe (or
>> > block of stripes) so the numbers aren't exactly on the interval.
>>
>> I see them as well during checks. Although I can't find documentation
>> stating so I regard them as normal.
>> --
>
> % man mdadm
>
> Search for "RebuildStarted"
>
>            RebuildStarted
>                   An  md array started reconstruction. (syslog priority: Warn-
>                   ing)
>
>
>            RebuildNN
>                   Where NN is a two-digit number (ie. 05, 48). This  indicates
>                   that  rebuild has passed that many percent of the total. The
>                   events are generated with fixed increment since 0. Increment
>                   size  may be specified with a commandline option (default is
>                   20). (syslog priority: Warning)
>
>
>
> This is in a section which starts
>
> MONITOR MODE
>        Usage: mdadm --monitor options... devices...
>
>
>        This usage causes mdadm to periodically poll a number of md arrays  and
>        to report on any events noticed.  mdadm will never exit once it decides
>        that there are arrays to be checked, so it should normally  be  run  in
>        the background.
>
>
> I guess that doesn't explicitly say it is normal, but that is the intent :-)
>
> They should be generated from recovery, resync, reshape, check, repair and
> anything else that might be added which processes the whole array like that.
> I guess "Rebuild" isn't a very generic word.. but
>    "StuffStarted"
>    "Stuff20"
>    "StuffFinished"
> probably wouldn't go down well either.
>
>
> Thanks,
> NeilBrown
>