[Drbd-dev] DRBD8: Resync stalled at 100% due to race condition

* [Drbd-dev] DRBD8: Resync stalled at 100% due to race condition
       [not found] <BD7042533C2F8943A6A4257A9E31C454F47906@EXNA.corp.stratus.com>
@ 2007-05-24 12:41 ` Montrose, Ernest
  2007-06-01 14:19   ` Philipp Reisner
  2007-06-04  9:08   ` Philipp Reisner
  0 siblings, 2 replies; 5+ messages in thread
From: Montrose, Ernest @ 2007-05-24 12:41 UTC (permalink / raw)
  To: drbd-dev

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

Hi all,
We are seeing a problem where a resync hangs on the SyncSource at the
end.  The SyncTarget finished OK and shows Connected. The signature on
the SyncSource is:
 
 ns:364900 nr:13389364 dw:13754324 dr:800327 al:165 bm:959 lo:0 pe:0
ua:0 ap:0
    [===================>] sync'ed:100.0% (0/0)K
    stalled

What I think is happening is that there is a race condition where
drbd_resync_finished() races receive_state() in this manner:
1)  The resync finished on drbd0 and we enter drbd_resync_finished().
But before it can set the stated to Connected, drbd15 which is a higher
priority device starts syncing. This puts drbd0 in PausedSyncS from
SyncSource.
 
2) Drbd_resync_finished() for drbd0 now tries to go to Connected from
PausedSyncS.  The logs below prints this transition but the transition
was not actually commited since we print before we actually assign the
new values. 
 
3) At this precise moment, another thread calls receive_state().
Receive_state() is entered with a state of "PausedSyncS".  It skips the
drbd_sync_handshake() because of that.  However, before reaching the end
of receive_state() the drbd0 state change from drbd_request_finished()
is commited for real. So the state is Connected for drbd0.
 
4) By the time receive_state calls _drbd_set_state()  we have
os=Connected and ns=PausedSyncS because receive_state() had cached the
state in nconn early without the req_lock held.  The mdev value had
changed while the cached value is being used. 
 
5) drbd0 now transitions from Connected to PausedSyncS.
 
6) Because of 5 above we transition from PausedSyncS to SyncSource but
the other side is connected and Uptodate ...So we're stuck.
 
I think this is the result of receive_state() being a bit racy.  I
include a patch that may at least help illustrate the issue if not fix
it as I am not sure the req_lock can be held this early without causing
a deadlock or other perfomance issues.
 
Here are the logs for completeness:
 
So on syncsource:
May  8 03:50:12 bruce kernel: drbd0: Began resync as SyncSource (will
sync 840 KB [210 bits set]).
May  8 03:50:12 bruce kernel: drbd0: Writing meta data super block now.
May  8 03:50:13 bruce kernel: drbd0: conn( SyncSource -> PausedSyncS )
aftr_isp( 0 -> 1 )
May  8 03:50:13 bruce kernel: drbd0: Resync suspended
May  8 03:50:13 bruce kernel: drbd0: Resync done (total 1 sec; paused 0
sec; 840 K/sec)
May  8 03:50:13 bruce kernel: drbd0:  uuid[History_start] now
1DCA5DA245F96038
May  8 03:50:13 bruce kernel: drbd0:  uuid[Bitmap] now 0000000000000000
May  8 03:50:13 bruce kernel: drbd0: conn( PausedSyncS -> Connected )
pdsk( Inconsistent -> UpToDate )
May  8 03:50:13 bruce kernel: drbd0: conn( Connected -> PausedSyncS )
peer_isp( 0 -> 1 )
May  8 03:50:13 bruce kernel: drbd0: Writing meta data super block now.
May  8 03:50:13 bruce kernel: drbd0: peer_isp( 1 -> 0 )
May  8 03:50:13 bruce kernel: drbd0: conn( PausedSyncS -> SyncSource )
aftr_isp( 1 -> 0 )
May  8 03:50:13 bruce kernel: drbd0: Syncer continues.


On the syncTarget:
May  8 03:50:13 dick kernel: drbd0: conn( WFSyncUUID -> SyncTarget )
disk( UpToDate -> Inconsistent )
May  8 03:50:13 dick kernel: drbd0: Began resync as SyncTarget (will
sync 840 KB [210 bits set]).
May  8 03:50:13 dick kernel: drbd0: Writing meta data super block now.
May  8 03:50:14 dick kernel: drbd0: Resync done (total 1 sec; paused 0
sec; 840 K/sec)
May  8 03:50:14 dick kernel: drbd0:  uuid[Bitmap] now A10989D4FAD4C4BB
May  8 03:50:14 dick kernel: drbd0:  uuid[History_start] now
B2E9873EF8AC35CB
May  8 03:50:14 dick kernel: drbd0:  uuid[History_end] now
161E8961AB2B5473
May  8 03:50:14 dick kernel: drbd0:  uuid[History_start] now
A10989D4FAD4C4BB
May  8 03:50:14 dick kernel: drbd0:  uuid[Bitmap] now 1DCA5DA245F96038
May  8 03:50:14 dick kernel: drbd0:  uuid[Current] now 8B19AE5BFEDF83D4
May  8 03:50:14 dick kernel: drbd0:  uuid[History_start] now
1DCA5DA245F96038
May  8 03:50:14 dick kernel: drbd0:  uuid[Bitmap] now 0000000000000000
May  8 03:50:14 dick kernel: drbd0: conn( SyncTarget -> Connected )
disk( Inconsistent -> UpToDate )
May  8 03:50:14 dick kernel: drbd0: Writing meta data super block now.

EM--

[-- Attachment #2: resync_hangs_2290.patch --]
[-- Type: application/octet-stream, Size: 882 bytes --]

Index: drbd/drbd_receiver.c
===================================================================

--- drbd/drbd_receiver.c	(revision 14387)
+++ drbd/drbd_receiver.c	(working copy)
@@ -2398,6 +2398,8 @@
 	if (drbd_recv(mdev, h->payload, h->length) != h->length)
 		return FALSE;
 
+       spin_lock_irq(&mdev->req_lock);
+   
 	nconn = mdev->state.conn;
 	if (nconn == WFReportParams ) nconn = Connected;
 
@@ -2409,7 +2411,11 @@
 		nconn=drbd_sync_handshake(mdev,peer_state.role,peer_state.disk);
 		dec_local(mdev);
 
-		if(nconn == conn_mask) return FALSE;
+		if(nconn == conn_mask) {
+                 spin_unlock_irq(&mdev->req_lock);
+                 return FALSE;
+              }
+              
 	}
 
 	if (mdev->state.conn > WFReportParams ) {
@@ -2424,7 +2430,6 @@
 		}
 	}
 
-	spin_lock_irq(&mdev->req_lock);
 	os = mdev->state;
 	ns.i = mdev->state.i;
 	ns.conn = nconn;

^ permalink raw reply	[flat|nested] 5+ messages in thread