Re: raid1 data corruption during resync

On Tue, 2 Sep 2014 20:18:06 -0500 Brassow Jonathan [off-list ref]
wrote:

On Sep 2, 2014, at 6:55 PM, NeilBrown wrote:

quoted

On Tue, 2 Sep 2014 15:07:26 -0700 Eivind Sarto [off-list ref] wrote:

quoted

On Sep 2, 2014, at 12:24 PM, Brassow Jonathan [off-list ref] wrote:

quoted

On Aug 29, 2014, at 2:29 PM, Eivind Sarto wrote:

quoted

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