Re: raid1 data corruption during resync

[NeilBrown <neilb@suse.de>]

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

On Tue, 2 Sep 2014 20:18:06 -0500 Brassow Jonathan <jbrassow@redhat.com>
wrote:

> 
> On Sep 2, 2014, at 6:55 PM, NeilBrown wrote:
> 
> > On Tue, 2 Sep 2014 15:07:26 -0700 Eivind Sarto <eivindsarto@gmail.com> wrote:
> > 
> >> 
> >> On Sep 2, 2014, at 12:24 PM, Brassow Jonathan <jbrassow@redhat.com> wrote:
> >> 
> >>> 
> >>> On Aug 29, 2014, at 2:29 PM, Eivind Sarto wrote:
> >>> 
> >>>> I am seeing occasional data corruption during raid1 resync.
> >>>> Reviewing the raid1 code, I suspect that commit 79ef3a8aa1cb1523cc231c9a90a278333c21f761 introduced a bug.
> >>>> Prior to this commit raise_barrier() used to wait for conf->nr_pending to become zero.  It no longer does this.
> >>>> It is not easy to reproduce the corruption, so I wanted to ask about the following potential fix while I am still testing it.
> >>>> Once I validate that the fix indeed works, I will post a proper patch.
> >>>> Do you have any feedback?
> >>>> 
> >>>> — drivers/md/raid1.c	2014-08-22 15:19:15.000000000 -0700
> >>>> +++ /tmp/raid1.c	2014-08-29 12:07:51.000000000 -0700
> >>>> @@ -851,7 +851,7 @@ static void raise_barrier(struct r1conf 
> >>>> 	 *    handling.
> >>>> 	 */
> >>>> 	wait_event_lock_irq(conf->wait_barrier,
> >>>> -			    !conf->array_frozen &&
> >>>> +			    !conf->array_frozen && !conf->nr_pending &&
> >>>> 			    conf->barrier < RESYNC_DEPTH &&
> >>>> 			    (conf->start_next_window >=
> >>>> 			     conf->next_resync + RESYNC_SECTORS),
> >>> 
> >>> This patch does not work - at least, it doesn't fix the issues I'm seeing.  My system hangs (in various places, like the resync thread) after commit 79ef3a8.  When testing this patch, I also added some code to dm-raid.c to allow me to print-out some of the variables when I encounter a problem.  After applying this patch and printing the variables, I see:
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: start_next_window = 12288
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: current_window_requests = -46
> >>> 5257
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: next_window_requests = -11562
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: nr_pending = 0
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: nr_waiting = 0
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: nr_queued  = 0
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: barrier = 1
> >>> Sep  2 14:04:15 bp-01 kernel: device-mapper: raid: array_frozen = 0
> >>> 
> >>> Some of those values look pretty bizarre to me and suggest the accounting is pretty messed up.
> >>> 
> >>> brassow
> >>> 
> >> 
> >> After reviewing commit 79ef3a8aa1cb1523cc231c9a90a278333c21f761 I notice that wait_barrier() will now only exclude writes.  User reads are not excluded even if the fall within the resync window.
> >> The old implementation used to exclude both reads and writes while resync-IO is active.
> >> Could this be a cause of data corruption?
> >> 
> > 
> > Could be.
> > From read_balance:
> > 
> > 	if (conf->mddev->recovery_cp < MaxSector &&
> > 	    (this_sector + sectors >= conf->next_resync))
> > 		choose_first = 1;
> > 	else
> > 		choose_first = 0;
> > 
> > This used to be safe because a read immediately before next_resync would wait
> > until all resync requests completed.  But now that read requests don't block
> > it isn't safe.
> > Probably best to make this:
> > 
> >    choose_first = (conf->mddev->recovery_cp < this_sector + sectors);
> > 
> > Can you test that?
> 
> Unfortunately, I doubt very much that that will solve the issue that I am seeing.  (Although, I'd welcome this fix also.)
> 
> I have predominantly been testing RHEL kernels, but I've seen this with the latest upstream kernel as well.  When doing fault testing, like failing a drive while the resync is happening, the processes can become hung.  Here's one example, but they vary:
> 
> INFO: task mdX_resync:11334 blocked for more than 120 seconds.                  
>       Not tainted 2.6.32-497.el6.x86_64 #1                                      
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.       
> mdX_resync    D 0000000000000000     0 11334      2 0x00000080                  
>  ffff8801fada5be0 0000000000000046 ffff88021a3bcc00 0000000300000001            
>  ffff880218b92200 ffff880218668f50 0000000000000282 0000000000000003            
>  0000000000000001 0000000000000282 ffff88021bfb45f8 ffff8801fada5fd8            
> Call Trace:                                                                     
>  [<ffffffff8140e439>] ? md_wakeup_thread+0x39/0x70                              
>  [<ffffffffa02b81dd>] sync_request+0x26d/0xb90 [raid1]                          
>  [<ffffffff81064b90>] ? default_wake_function+0x0/0x20                          
>  [<ffffffff810577e9>] ? __wake_up_common+0x59/0x90                              
>  [<ffffffff8109eb00>] ? autoremove_wake_function+0x0/0x40                       
>  [<ffffffff8105bd23>] ? __wake_up+0x53/0x70                                     
>  [<ffffffff81414a47>] md_do_sync+0x6c7/0xd20                                    
>  [<ffffffff814154f5>] md_thread+0x115/0x150                                     
>  [<ffffffff814153e0>] ? md_thread+0x0/0x150                                     
>  [<ffffffff8109e66e>] kthread+0x9e/0xc0                                         
>  [<ffffffff8100c20a>] child_rip+0xa/0x20                                        
>  [<ffffffff8109e5d0>] ? kthread+0x0/0xc0                                        
>  [<ffffffff8100c200>] ? child_rip+0x0/0x20                                      
> 
> 
> and...
> 
> 
> INFO: task kjournald:10732 blocked for more than 120 seconds.                   
>       Not tainted 2.6.32-497.el6.x86_64 #1                                      
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.       
> kjournald     D 0000000000000008     0 10732      2 0x00000080                  
>  ffff8801d71238b0 0000000000000046 0000000000000000 0000000300000001            
>  ffff880218b92200 ffff880218668f50 000003783fd7424b 0000000000000003            
>  0000000000000001 000000010035a163 ffff880219135af8 ffff8801d7123fd8            
> Call Trace:                                                                     
>  [<ffffffffa02b463f>] wait_barrier+0xcf/0x280 [raid1]                           
>  [<ffffffff8109eb00>] ? autoremove_wake_function+0x0/0x40                       
>  [<ffffffffa02b71bf>] make_request+0x8f/0xe40 [raid1]                           
>  [<ffffffff81126af5>] ? mempool_alloc_slab+0x15/0x20                            
>  [<ffffffff81126c93>] ? mempool_alloc+0x63/0x140                                
>  [<ffffffff811c9d6b>] ? bio_alloc_bioset+0x5b/0xf0                              
>  [<ffffffffa02cf018>] raid_map+0x18/0x20 [dm_raid]
> 
> Bisecting has revealed that the commit that is the subject of this thread is the root of the problem.  It does take a long time to reproduce the issue with the scripts that I have, but if there is info I can get you, let me know.
> 
>  brassow

Thanks for the details Jon.  I don't suppose you have a stack trace from an
upstream kernel?  Not that I doubt you have one, and I suspect it is very
similar.  But I've learnt not to trust "suspect" and "presume" and "no doubt".

I'll have a look anyway.

Thanks,
NeilBrown

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