raid5 Journal Recovery Bug

raid5 Journal Recovery Bug

[Logan Gunthorpe]

Hi Song,

I'm wondering if you can help shed some light on a bug I'm trying to
track down.

We're hitting the BUG_ON in handle_parity_checks5() that tests to ensure
R5_UPTODATE is set for a failed disk in a stripe[1].

We hit this in our test suite somewhat rarely when the journal is
enabled doing device removal and recovery tests. We've concocted a test
that can hit it in under ten minutes.

After some debugging I've found that the stripe that hits the BUG_ON is
hitting a conditional in handle_stripe_fill() for stripes that are in
the journal with a failed disk[2]. This check was added in 2017 by your
patch:

   07e83364845e ("md/r5cache: shift complex rmw from read path to write
path")

A stripe that hits the bug has one injournal dev, and one failed dev and
does not have STRIPE_R5C_CACHING set and therefore hits the conditional
and returns from handle_stripe_fill() without calling fetch_block() or
doing anything else to change the flow of execution. Normally,
fetch_block() would set STRIPE_COMPUTE_RUN to recompute the missing
disk, however that gets skipped for this case. After returning from
handle_stripe_fill(), handle_stripe() will then call
handle_parity_checks5() because STRIPE_COMPUTE_RUN was not set and this
will immediately hit the BUG_ON, because nothing has computed the disk
and set it UPTODATE yet.

I can't say I fully understand the patch that added this, so I don't
really understand why that conditional is there or what it's trying to
accomplish and thus I don't know what the correct solution might be.

Any thoughts?

Thanks,

Logan


[1]
https://elixir.bootlin.com/linux/v6.0-rc1/source/drivers/md/raid5.c#L4381
[2]
https://elixir.bootlin.com/linux/v6.0-rc1/source/drivers/md/raid5.c#L4050

Re: raid5 Journal Recovery Bug

[Song Liu]

On Fri, Aug 19, 2022 at 3:52 PM Logan Gunthorpe <logang@deltatee.com> wrote:
>
> Hi Song,
>
> I'm wondering if you can help shed some light on a bug I'm trying to
> track down.
>
> We're hitting the BUG_ON in handle_parity_checks5() that tests to ensure
> R5_UPTODATE is set for a failed disk in a stripe[1].
>
> We hit this in our test suite somewhat rarely when the journal is
> enabled doing device removal and recovery tests. We've concocted a test
> that can hit it in under ten minutes.
>
> After some debugging I've found that the stripe that hits the BUG_ON is
> hitting a conditional in handle_stripe_fill() for stripes that are in
> the journal with a failed disk[2]. This check was added in 2017 by your
> patch:
>
>    07e83364845e ("md/r5cache: shift complex rmw from read path to write
> path")
>
> A stripe that hits the bug has one injournal dev, and one failed dev and
> does not have STRIPE_R5C_CACHING set and therefore hits the conditional
> and returns from handle_stripe_fill() without calling fetch_block() or
> doing anything else to change the flow of execution. Normally,
> fetch_block() would set STRIPE_COMPUTE_RUN to recompute the missing
> disk, however that gets skipped for this case. After returning from
> handle_stripe_fill(), handle_stripe() will then call
> handle_parity_checks5() because STRIPE_COMPUTE_RUN was not set and this
> will immediately hit the BUG_ON, because nothing has computed the disk
> and set it UPTODATE yet.
>
> I can't say I fully understand the patch that added this, so I don't
> really understand why that conditional is there or what it's trying to
> accomplish and thus I don't know what the correct solution might be.
>
> Any thoughts?

Could you please add some printk so that we know which condition triggered
handle_stripe_fill() here:

        if (s.to_read || s.non_overwrite
            || (s.to_write && s.failed)
            || (s.syncing && (s.uptodate + s.compute < disks))
            || s.replacing
            || s.expanding)
                handle_stripe_fill(sh, &s, disks);

This would help us narrow down to the exact condition. I guess it is
"(s.to_write && s.failed)", but I am not quite sure.

Thanks,
Song

Re: raid5 Journal Recovery Bug

[Logan Gunthorpe]

On 2022-08-22 01:04, Song Liu wrote:
> Could you please add some printk so that we know which condition triggered
> handle_stripe_fill() here:
> 
>         if (s.to_read || s.non_overwrite
>             || (s.to_write && s.failed)
>             || (s.syncing && (s.uptodate + s.compute < disks))
>             || s.replacing
>             || s.expanding)
>                 handle_stripe_fill(sh, &s, disks);
> 
> This would help us narrow down to the exact condition. I guess it is
> "(s.to_write && s.failed)", but I am not quite sure.

Ok, I hit this bug on a stripe and got these values for the call:

  to_read       = 0
  non_overwrite = 0
  to_write	= 0	
  failed	= 1
  syncing	= 1
  uptodate	= 2
  compute	= 0
  disks		= 3
  replacing	= 0
  expanding	= 0

So it's actually the "(s.syncing && (s.uptodate + s.compute < disks))"
condition that is getting hit.

Thanks,

Logan

Re: raid5 Journal Recovery Bug

[Song Liu]

On Mon, Aug 22, 2022 at 9:28 AM Logan Gunthorpe <logang@deltatee.com> wrote:
>
>
>
> On 2022-08-22 01:04, Song Liu wrote:
> > Could you please add some printk so that we know which condition triggered
> > handle_stripe_fill() here:
> >
> >         if (s.to_read || s.non_overwrite
> >             || (s.to_write && s.failed)
> >             || (s.syncing && (s.uptodate + s.compute < disks))
> >             || s.replacing
> >             || s.expanding)
> >                 handle_stripe_fill(sh, &s, disks);
> >
> > This would help us narrow down to the exact condition. I guess it is
> > "(s.to_write && s.failed)", but I am not quite sure.
>
> Ok, I hit this bug on a stripe and got these values for the call:
>
>   to_read       = 0
>   non_overwrite = 0
>   to_write      = 0
>   failed        = 1
>   syncing       = 1
>   uptodate      = 2
>   compute       = 0
>   disks         = 3
>   replacing     = 0
>   expanding     = 0
>
> So it's actually the "(s.syncing && (s.uptodate + s.compute < disks))"
> condition that is getting hit.

Thanks for the information! So the stripe is syncing. Could you please
try whether the following fixes the issue?

Thanks,
Song

diff --git i/drivers/md/raid5.c w/drivers/md/raid5.c
index 5cabdbbac48b..0580ebb11801 100644
--- i/drivers/md/raid5.c
+++ w/drivers/md/raid5.c
@@ -3952,7 +3952,7 @@ static void handle_stripe_fill(struct stripe_head *sh,
                 * back cache (prexor with orig_page, and then xor with
                 * page) in the read path
                 */
-               if (s->injournal && s->failed) {
+               if (s->to_read && s->injournal && s->failed) {
                        if (test_bit(STRIPE_R5C_CACHING, &sh->state))
                                r5c_make_stripe_write_out(sh);
                        goto out;

Re: raid5 Journal Recovery Bug

[Logan Gunthorpe]

On 2022-08-22 13:12, Song Liu wrote:
> On Mon, Aug 22, 2022 at 9:28 AM Logan Gunthorpe <logang@deltatee.com> wrote:
>>
>>
>>
>> On 2022-08-22 01:04, Song Liu wrote:
>>> Could you please add some printk so that we know which condition triggered
>>> handle_stripe_fill() here:
>>>
>>>         if (s.to_read || s.non_overwrite
>>>             || (s.to_write && s.failed)
>>>             || (s.syncing && (s.uptodate + s.compute < disks))
>>>             || s.replacing
>>>             || s.expanding)
>>>                 handle_stripe_fill(sh, &s, disks);
>>>
>>> This would help us narrow down to the exact condition. I guess it is
>>> "(s.to_write && s.failed)", but I am not quite sure.
>>
>> Ok, I hit this bug on a stripe and got these values for the call:
>>
>>   to_read       = 0
>>   non_overwrite = 0
>>   to_write      = 0
>>   failed        = 1
>>   syncing       = 1
>>   uptodate      = 2
>>   compute       = 0
>>   disks         = 3
>>   replacing     = 0
>>   expanding     = 0
>>
>> So it's actually the "(s.syncing && (s.uptodate + s.compute < disks))"
>> condition that is getting hit.
> 
> Thanks for the information! So the stripe is syncing. Could you please
> try whether the following fixes the issue?

Yup, thanks! Looks like that fixes my test case. I can do more general
testing on it later this week.

Logan

Re: raid5 Journal Recovery Bug

[Song Liu]

On Mon, Aug 22, 2022 at 1:40 PM Logan Gunthorpe <logang@deltatee.com> wrote:
>
>
>
> On 2022-08-22 13:12, Song Liu wrote:
> > On Mon, Aug 22, 2022 at 9:28 AM Logan Gunthorpe <logang@deltatee.com> wrote:
> >>
> >>
> >>
> >> On 2022-08-22 01:04, Song Liu wrote:
> >>> Could you please add some printk so that we know which condition triggered
> >>> handle_stripe_fill() here:
> >>>
> >>>         if (s.to_read || s.non_overwrite
> >>>             || (s.to_write && s.failed)
> >>>             || (s.syncing && (s.uptodate + s.compute < disks))
> >>>             || s.replacing
> >>>             || s.expanding)
> >>>                 handle_stripe_fill(sh, &s, disks);
> >>>
> >>> This would help us narrow down to the exact condition. I guess it is
> >>> "(s.to_write && s.failed)", but I am not quite sure.
> >>
> >> Ok, I hit this bug on a stripe and got these values for the call:
> >>
> >>   to_read       = 0
> >>   non_overwrite = 0
> >>   to_write      = 0
> >>   failed        = 1
> >>   syncing       = 1
> >>   uptodate      = 2
> >>   compute       = 0
> >>   disks         = 3
> >>   replacing     = 0
> >>   expanding     = 0
> >>
> >> So it's actually the "(s.syncing && (s.uptodate + s.compute < disks))"
> >> condition that is getting hit.
> >
> > Thanks for the information! So the stripe is syncing. Could you please
> > try whether the following fixes the issue?
>
> Yup, thanks! Looks like that fixes my test case. I can do more general
> testing on it later this week.

Awesome! Could you please run more tests and submit the patch?

Thanks,
Song