BUG?: RAID6 reshape hung in reshape_request

BUG?: RAID6 reshape hung in reshape_request

[David Wahler]

Hi,

I'm trying to reshape a 4-disk RAID6 array by adding a fifth "missing"
drive. Maybe that's a weird thing to do, so for context: I'm
converting from a 3-disk RAID10, by creating a new RAID6 with the
three new disks and then moving disks one at a time between the
arrays. I did it this way so that I could test for problems with the
reshape procedure before irrevocably modifying more than one of the
original disks.

(I do also have an offsite backup of the most important data, but it's
inconvenient to access and I'm hoping not to need it.)

Anyway, the reshape was going fine until about 70% completion, and
then it got stuck. I've tried rebooting a few times: the array can be
assembled in read-only mode, but as soon as it goes read-write and the
reshape process continues, it gets through a few megabytes and hangs.
At that point, any other process that tries to access the array also
hangs uninterruptibly.

Here's what shows up in dmesg:

[  721.183225] INFO: task md127_resync:1730 blocked for more than 120 seconds.
[  721.183978]       Not tainted 4.0.0 #1
[  721.184751] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  721.185514] md127_resync    D ffff88042ea94440     0  1730      2 0x00000000
[  721.185516]  ffff88041a24ed20 0000000000000400 ffff88041ca82a20
0000000000000246
[  721.185518]  ffff8800b8b5ffd8 ffff8800b8b5fbf0 ffff880419035a30
0000000000000004
[  721.185519]  ffff8800b8b5fd1c ffff88040e91d000 ffffffff8155c73f
ffff880419035800
[  721.185520] Call Trace:
[  721.185526]  [<ffffffff8155c73f>] ? schedule+0x2f/0x80
[  721.185530]  [<ffffffffa0888390>] ? reshape_request+0x1e0/0x8f0 [raid456]
[  721.185533]  [<ffffffff810a86f0>] ? wait_woken+0x90/0x90
[  721.185535]  [<ffffffffa0888dae>] ? sync_request+0x30e/0x390 [raid456]
[  721.185547]  [<ffffffffa02cbf89>] ? is_mddev_idle+0xc9/0x130 [md_mod]
[  721.185550]  [<ffffffffa02cf432>] ? md_do_sync+0x802/0xd30 [md_mod]
[  721.185555]  [<ffffffff8101c356>] ? native_sched_clock+0x26/0x90
[  721.185558]  [<ffffffffa02cbb30>] ? md_safemode_timeout+0x50/0x50 [md_mod]
[  721.185561]  [<ffffffffa02cbc56>] ? md_thread+0x126/0x130 [md_mod]
[  721.185563]  [<ffffffff8155c0c0>] ? __schedule+0x2a0/0x8f0
[  721.185565]  [<ffffffffa02cbb30>] ? md_safemode_timeout+0x50/0x50 [md_mod]
[  721.185568]  [<ffffffff81089403>] ? kthread+0xd3/0xf0
[  721.185570]  [<ffffffff81089330>] ? kthread_create_on_node+0x180/0x180
[  721.185572]  [<ffffffff81560598>] ? ret_from_fork+0x58/0x90
[  721.185574]  [<ffffffff81089330>] ? kthread_create_on_node+0x180/0x180

And the output of mdadm --detail/-E:
https://gist.github.com/anonymous/0b090668b56ef54bb2f0

I was originally running a Debian 3.16.0 kernel, and then upgraded to
4.0 to see if it would help, but no such luck.

Does anyone have any suggestions? Since the data on the array seems to
be fine, hopefully there's a solution that doesn't involve re-creating
it from scratch and restoring from backups.

Thanks,
-- David

Re: BUG?: RAID6 reshape hung in reshape_request

[NeilBrown]

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

On Sat, 25 Apr 2015 16:35:24 -0500 David Wahler <dwahler@gmail.com> wrote:

> Hi,
> 
> I'm trying to reshape a 4-disk RAID6 array by adding a fifth "missing"
> drive. Maybe that's a weird thing to do, so for context: I'm
> converting from a 3-disk RAID10, by creating a new RAID6 with the
> three new disks and then moving disks one at a time between the
> arrays. I did it this way so that I could test for problems with the
> reshape procedure before irrevocably modifying more than one of the
> original disks.
> 
> (I do also have an offsite backup of the most important data, but it's
> inconvenient to access and I'm hoping not to need it.)
> 
> Anyway, the reshape was going fine until about 70% completion, and
> then it got stuck. I've tried rebooting a few times: the array can be
> assembled in read-only mode, but as soon as it goes read-write and the
> reshape process continues, it gets through a few megabytes and hangs.
> At that point, any other process that tries to access the array also
> hangs uninterruptibly.
> 
> Here's what shows up in dmesg:
> 
> [  721.183225] INFO: task md127_resync:1730 blocked for more than 120 seconds.
> [  721.183978]       Not tainted 4.0.0 #1
> [  721.184751] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [  721.185514] md127_resync    D ffff88042ea94440     0  1730      2 0x00000000
> [  721.185516]  ffff88041a24ed20 0000000000000400 ffff88041ca82a20
> 0000000000000246
> [  721.185518]  ffff8800b8b5ffd8 ffff8800b8b5fbf0 ffff880419035a30
> 0000000000000004
> [  721.185519]  ffff8800b8b5fd1c ffff88040e91d000 ffffffff8155c73f
> ffff880419035800
> [  721.185520] Call Trace:
> [  721.185526]  [<ffffffff8155c73f>] ? schedule+0x2f/0x80
> [  721.185530]  [<ffffffffa0888390>] ? reshape_request+0x1e0/0x8f0 [raid456]
> [  721.185533]  [<ffffffff810a86f0>] ? wait_woken+0x90/0x90
> [  721.185535]  [<ffffffffa0888dae>] ? sync_request+0x30e/0x390 [raid456]
> [  721.185547]  [<ffffffffa02cbf89>] ? is_mddev_idle+0xc9/0x130 [md_mod]
> [  721.185550]  [<ffffffffa02cf432>] ? md_do_sync+0x802/0xd30 [md_mod]
> [  721.185555]  [<ffffffff8101c356>] ? native_sched_clock+0x26/0x90
> [  721.185558]  [<ffffffffa02cbb30>] ? md_safemode_timeout+0x50/0x50 [md_mod]
> [  721.185561]  [<ffffffffa02cbc56>] ? md_thread+0x126/0x130 [md_mod]
> [  721.185563]  [<ffffffff8155c0c0>] ? __schedule+0x2a0/0x8f0
> [  721.185565]  [<ffffffffa02cbb30>] ? md_safemode_timeout+0x50/0x50 [md_mod]
> [  721.185568]  [<ffffffff81089403>] ? kthread+0xd3/0xf0
> [  721.185570]  [<ffffffff81089330>] ? kthread_create_on_node+0x180/0x180
> [  721.185572]  [<ffffffff81560598>] ? ret_from_fork+0x58/0x90
> [  721.185574]  [<ffffffff81089330>] ? kthread_create_on_node+0x180/0x180
> 
> And the output of mdadm --detail/-E:
> https://gist.github.com/anonymous/0b090668b56ef54bb2f0

What is wrong with simply including this directly in the email???

Anyway:

  Bad Block Log : 512 entries available at offset 72 sectors - bad blocks present.

that is the only thing that looks at all interesting.  Particularly the last
3 words.
What does
   mdadm --examine-badblocks /dev/sd[cde]1
show?

NeilBrown


> 
> I was originally running a Debian 3.16.0 kernel, and then upgraded to
> 4.0 to see if it would help, but no such luck.
> 
> Does anyone have any suggestions? Since the data on the array seems to
> be fine, hopefully there's a solution that doesn't involve re-creating
> it from scratch and restoring from backups.
> 
> Thanks,
> -- David
> --
> 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


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Fwd: BUG?: RAID6 reshape hung in reshape_request

[David Wahler]

[oops, forgot to cc the list]

On Sun, Apr 26, 2015 at 8:20 PM, NeilBrown <neilb@suse.de> wrote:
>> And the output of mdadm --detail/-E:
>> https://gist.github.com/anonymous/0b090668b56ef54bb2f0
>
> What is wrong with simply including this directly in the email???

My bad; I wasn't sure whether it was appropriate to paste such a long
dump inline.

> Anyway:
>
>   Bad Block Log : 512 entries available at offset 72 sectors - bad blocks present.
>
> that is the only thing that looks at all interesting.  Particularly the last
> 3 words.
> What does
>    mdadm --examine-badblocks /dev/sd[cde]1
> show?

root@ceres:~# mdadm --examine-badblocks /dev/sd[cde]1
Bad-blocks on /dev/sdc1:
          3699640928 for 32 sectors
Bad-blocks on /dev/sdd1:
          3699640928 for 32 sectors
Bad-blocks on /dev/sde1:
          3699640928 for 32 sectors

Hmm, that seems kind of odd to me. For what it's worth, all four
drives passed a SMART self-test, and "dd > /dev/null" completed
without errors on all of them. I just read about the "badblocks" tool
and I'm running it now.

-- David

Re: BUG?: RAID6 reshape hung in reshape_request

[NeilBrown]

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

On Sun, 26 Apr 2015 20:56:58 -0500 David Wahler <dwahler@gmail.com> wrote:

> [oops, forgot to cc the list]
> 
> On Sun, Apr 26, 2015 at 8:20 PM, NeilBrown <neilb@suse.de> wrote:
> >> And the output of mdadm --detail/-E:
> >> https://gist.github.com/anonymous/0b090668b56ef54bb2f0
> >
> > What is wrong with simply including this directly in the email???
> 
> My bad; I wasn't sure whether it was appropriate to paste such a long
> dump inline.
> 
> > Anyway:
> >
> >   Bad Block Log : 512 entries available at offset 72 sectors - bad blocks present.
> >
> > that is the only thing that looks at all interesting.  Particularly the last
> > 3 words.
> > What does
> >    mdadm --examine-badblocks /dev/sd[cde]1
> > show?
> 
> root@ceres:~# mdadm --examine-badblocks /dev/sd[cde]1
> Bad-blocks on /dev/sdc1:
>           3699640928 for 32 sectors
> Bad-blocks on /dev/sdd1:
>           3699640928 for 32 sectors
> Bad-blocks on /dev/sde1:
>           3699640928 for 32 sectors
> 
> Hmm, that seems kind of odd to me. For what it's worth, all four
> drives passed a SMART self-test, and "dd > /dev/null" completed
> without errors on all of them. I just read about the "badblocks" tool
> and I'm running it now.

The array is reshaping a RAID6 from 4->5 devices, so that is 2 data disks to
3 data disks.

Reshape pos'n : 5548735488 (5291.69 GiB 5681.91 GB)

so it is about 5.3TB through the array, so it has read about 2.6TB from the
devices and written about 1.7TB to the devices.

3699640928 sectors is about 1.8TB.  That seems a little too close to be a co-incidence. 

Maybe when reshape write to somewhere that is a bad-block, it gets confused.

On the other hand, when it copies from the 1.8TB address to the 1.2TB address
it should have record that it was bad-blocks that were being copied.  It
doesn't seem like it did.

I'll have to look at the code and try to figure out what is happening.

I don't think there is anything useful you can do in the mean time...

NeilBrown


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: BUG?: RAID6 reshape hung in reshape_request

[David Wahler]

On Mon, Apr 27, 2015 at 1:59 AM, NeilBrown <neilb@suse.de> wrote:
> On Sun, 26 Apr 2015 20:56:58 -0500 David Wahler <dwahler@gmail.com> wrote:
>
>> [oops, forgot to cc the list]
>>
>> On Sun, Apr 26, 2015 at 8:20 PM, NeilBrown <neilb@suse.de> wrote:
>> > Anyway:
>> >
>> >   Bad Block Log : 512 entries available at offset 72 sectors - bad blocks present.
>> >
>> > that is the only thing that looks at all interesting.  Particularly the last
>> > 3 words.
>> > What does
>> >    mdadm --examine-badblocks /dev/sd[cde]1
>> > show?
>>
>> root@ceres:~# mdadm --examine-badblocks /dev/sd[cde]1
>> Bad-blocks on /dev/sdc1:
>>           3699640928 for 32 sectors
>> Bad-blocks on /dev/sdd1:
>>           3699640928 for 32 sectors
>> Bad-blocks on /dev/sde1:
>>           3699640928 for 32 sectors
>>
>> Hmm, that seems kind of odd to me. For what it's worth, all four
>> drives passed a SMART self-test, and "dd > /dev/null" completed
>> without errors on all of them. I just read about the "badblocks" tool
>> and I'm running it now.
>
> The array is reshaping a RAID6 from 4->5 devices, so that is 2 data disks to
> 3 data disks.
>
> Reshape pos'n : 5548735488 (5291.69 GiB 5681.91 GB)
>
> so it is about 5.3TB through the array, so it has read about 2.6TB from the
> devices and written about 1.7TB to the devices.
>
> 3699640928 sectors is about 1.8TB.  That seems a little too close to be a co-incidence.
>
> Maybe when reshape write to somewhere that is a bad-block, it gets confused.
>
> On the other hand, when it copies from the 1.8TB address to the 1.2TB address
> it should have record that it was bad-blocks that were being copied.  It
> doesn't seem like it did.
>
> I'll have to look at the code and try to figure out what is happening.
>
> I don't think there is anything useful you can do in the mean time...
>
> NeilBrown
>

Thanks, I appreciate you taking the time to look at this.

GDB tells me that the address where the reshape is getting stuck
corresponds to drivers/md/raid5.c:4933. I also noticed that there's a
kernel thread "md127_raid6" occupying 100% of a CPU core. Here's a
representative stack for that thread (with line numbers added by me):

[<ffffffffa06aeb20>] raid_run_ops+0xbe0/0x1170 [raid456]
arch/x86/include/asm/bitops.h:311
[<ffffffffa06ab277>] ops_run_io+0x27/0x970 [raid456] drivers/md/raid5.c:742
[<ffffffffa06a9940>] ops_complete_reconstruct+0x0/0x1c0 [raid456]
drivers/md/raid5.c:1433
[<ffffffffa06b2a00>] handle_stripe+0xbd0/0x2650 [raid456]
drivers/md/raid5.c:4099
[<ffffffff810a3162>] pick_next_task_fair+0x652/0x850 kernel/sched/fair.c:5047
[<ffffffffa06b463d>] handle_active_stripes.isra.41+0x1bd/0x4b0
[raid456] drivers/md/raid5.c:5248
[<ffffffff810115eb>] __switch_to+0x14b/0x5d0 arch/x86/include/asm/paravirt.h:276
[<ffffffffa06b4d7c>] raid5d+0x44c/0x5b0 [raid456] drivers/md/raid5.c:5340
[<ffffffffa0760c56>] md_thread+0x126/0x130 [md_mod]
[<ffffffff810a86f0>] autoremove_wake_function+0x0/0x30
[<ffffffffa0760b30>] md_thread+0x0/0x130 [md_mod]
[<ffffffff81089403>] kthread+0xd3/0xf0
[<ffffffff81089330>] kthread+0x0/0xf0
[<ffffffff81560598>] ret_from_fork+0x58/0x90
[<ffffffff81089330>] kthread+0x0/0xf0
[<ffffffffffffffff>] 0xffffffffffffffff

And the output of running "perf record" for a few seconds followed by
"perf report":

# ========
# captured on: Mon Apr 27 12:07:01 2015
# hostname : ceres
# os release : 4.0.0
# perf version : 4.0.g39a880
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
# cpudesc : Intel(R) Core(TM) i3-4160 CPU @ 3.60GHz
# cpuid : GenuineIntel,6,60,3
# total memory : 16112348 kB
# cmdline : /home/david/software/linux/tools/perf/perf record -p 508
# event : name = cycles, type = 0, config = 0x0, config1 = 0x0,
config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest
= 1, precise_ip = 0, attr_mmap2 = 1, attr_mmap  = 1, attr_mmap_data =
0
# HEADER_CPU_TOPOLOGY info available, use -I to display
# HEADER_NUMA_TOPOLOGY info available, use -I to display
# pmu mappings: cpu = 4, software = 1, power = 6, uncore_imc = 7,
tracepoint = 2, breakpoint = 5
# ========
#
# Samples: 84K of event 'cycles'
# Event count (approx.): 76131836770
#
# Overhead  Command      Shared Object      Symbol
# ........  ...........  .................
...........................................
#
    41.90%  md127_raid6  [raid6_pq]         [k] raid6_avx24_gen_syndrome
    19.31%  md127_raid6  [raid456]          [k] analyse_stripe
     8.48%  md127_raid6  [raid456]          [k] ops_run_i
     4.05%  md127_raid6  [raid456]          [k] handle_stripe
     3.72%  md127_raid6  [raid456]          [k] ops_complete_reconstruct
     3.30%  md127_raid6  [kernel.kallsyms]  [k] __kernel_fpu_end
     3.07%  md127_raid6  [raid456]          [k] schedule_reconstruction
     3.01%  md127_raid6  [raid456]          [k] raid5_compute_sector
     1.42%  md127_raid6  [raid456]          [k] handle_active_stripes.isra.41
     1.33%  md127_raid6  [kernel.kallsyms]  [k] __kernel_fpu_begin
     1.33%  md127_raid6  [raid456]          [k] do_release_stripe
     1.16%  md127_raid6  [raid456]          [k] raid_run_ops
     1.14%  md127_raid6  [md_mod]           [k] md_is_badblock
     1.12%  md127_raid6  [raid456]          [k] set_syndrome_sources
     1.07%  md127_raid6  [kernel.kallsyms]  [k] _raw_spin_lock_irqsave
     0.93%  md127_raid6  [async_pq]         [k] async_gen_syndrome
     0.69%  md127_raid6  [raid456]          [k] release_stripe
     0.64%  md127_raid6  [md_mod]           [k] md_wakeup_thread
     0.54%  md127_raid6  [raid456]          [k] __release_stripe
     0.40%  md127_raid6  [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     0.22%  md127_raid6  [raid456]          [k] release_stripe_list
     0.20%  md127_raid6  [kernel.kallsyms]  [k] __wake_up_common
     0.17%  md127_raid6  [raid456]          [k] release_inactive_stripe_list
     0.16%  md127_raid6  [kernel.kallsyms]  [k] __wake_up
     0.13%  md127_raid6  [raid456]          [k] raid5d
     0.11%  md127_raid6  [kernel.kallsyms]  [k] _raw_spin_lock_irq
     0.10%  md127_raid6  [raid456]          [k] return_io
[...etc...]

I don't urgently need this array up and running, so I'm happy to leave
it in its current state for the next few days in case there's anything
else I can do to help track this down.

-- David

Re: BUG?: RAID6 reshape hung in reshape_request

[NeilBrown]

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

On Mon, 27 Apr 2015 12:20:50 -0500 David Wahler <dwahler@gmail.com> wrote:
> 
> I don't urgently need this array up and running, so I'm happy to leave
> it in its current state for the next few days in case there's anything
> else I can do to help track this down.

Thanks for the various status data.

I'm fairly easily able to reproduce the problem.  I clearly never thought
about 'reshape' when I was writing the bad_block handling.

You can allow the reshape to complete by the following hack:

diff --git a/drivers/md/raid5.c b/drivers/md/raid5.c
index 77dfd720aaa0..e6c68a450d4c 100644
--- a/drivers/md/raid5.c
+++ b/drivers/md/raid5.c
@@ -4306,7 +4306,7 @@ static void handle_stripe(struct stripe_head *sh)
 	 */
 	if (s.failed > conf->max_degraded) {
 		sh->check_state = 0;
-		sh->reconstruct_state = 0;
+//		sh->reconstruct_state = 0;
 		if (s.to_read+s.to_write+s.written)
 			handle_failed_stripe(conf, sh, &s, disks, &s.return_bi);
 		if (s.syncing + s.replacing)

It may not necessarily do exactly the right thing, but it won't be too bad.

I'm tempted to simply disable reshapes if there are bad blocks, but that
might not be necessary.

The presence of a 'bad block' can mean two things.

1/ The data is missing.  If there are enough bad blocks in a stripe then
   some data cannot be recovered.  In that case we can only let the 'grow'
   proceed if we record the destination blocks as 'bad', which isn't too hard.

2/ The media is faulty and writes fail.  A 'bad block' doesn't always mean
   this, but it can and it is hard to know if it does or not.
   This case only really matters when writing.  I could probably just
   over-write anyway and handle failure as we normally would.
   If the 'write' succeeds, I need to clear the 'bad block' record, but I
   think I do that anyway.

So I should be able to make it work.  I'll probably get mdadm to warn
strongly against reshaping an array with bad blocks though.

I'm going to have to study the code some more.

NeilBrown

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: BUG?: RAID6 reshape hung in reshape_request

[David Wahler]

On Tue, Apr 28, 2015 at 7:03 PM, NeilBrown <neilb@suse.de> wrote:
> On Mon, 27 Apr 2015 12:20:50 -0500 David Wahler <dwahler@gmail.com> wrote:
>>
>> I don't urgently need this array up and running, so I'm happy to leave
>> it in its current state for the next few days in case there's anything
>> else I can do to help track this down.
>
> Thanks for the various status data.
>
> I'm fairly easily able to reproduce the problem.  I clearly never thought
> about 'reshape' when I was writing the bad_block handling.
>
> You can allow the reshape to complete by the following hack:
>
> diff --git a/drivers/md/raid5.c b/drivers/md/raid5.c
> index 77dfd720aaa0..e6c68a450d4c 100644
> --- a/drivers/md/raid5.c
> +++ b/drivers/md/raid5.c
> @@ -4306,7 +4306,7 @@ static void handle_stripe(struct stripe_head *sh)
>          */
>         if (s.failed > conf->max_degraded) {
>                 sh->check_state = 0;
> -               sh->reconstruct_state = 0;
> +//             sh->reconstruct_state = 0;
>                 if (s.to_read+s.to_write+s.written)
>                         handle_failed_stripe(conf, sh, &s, disks, &s.return_bi);
>                 if (s.syncing + s.replacing)
>
> It may not necessarily do exactly the right thing, but it won't be too bad.

Yep, worked like a charm.

Running fsck afterwards found a dozen or so corrupted inodes. I'm not
sure whether that's because of the initial read failure that caused
the blocks to be marked as bad, or if it was aggravated by me
repeatedly interrupting the reshape.

Thanks again for the assistance.

-- David