[Drbd-dev] DRBD8: nodes deadlock in PausedSync{ST]

[Drbd-dev] DRBD8: nodes deadlock in PausedSync{ST]

[Montrose, Ernest]

[-- Attachment #1.1: Type: text/plain, Size: 7393 bytes --]

Hi all,
I have been struggling with a problem here where the nodes enter
PausedSync[T|S] and stay there.  
This happens when one node come up from a fresh attach, connect
sequence.  I think the issue happens this way. Say we have two volumes
drbd5 and drbd16 and we attempt to connect both of them at roughly the
same time.  Futhermore, drbd5 and 16 will require syncing say as sync
target. What I observe is this:
*	drbd16 is connecting and drbd5 is syncing. So 16 is paused isp=1
*	drbd16 enters receive_state() but before acquiring the req_lock
that thread loses the CPU to drbd5 that is finishing syncing.  After_isp
is cleared on 16 giving drbd16 the green light to continue syncing. So
far so good.
*	Now drbd16 resumes with the old peer_isp=1 
*	So now we are paused forever.
 
So I think receive_state() is just racy but I could be wrong. I am
really not sure how to fix this but I include a patch here that may help
to at least illustrate the problem. It seems close window for this
particular race somewhat.
 
Below are the original logs on the two nodes:
======Node 0 logs=====
Oct  4 03:38:11 node0 kernel: drbd5: Handshake successful: DRBD Network
Protocol version 86
Oct  4 03:38:12 node0 kernel: drbd5: drbd_sync_handshake:
Oct  4 03:38:12 node0 kernel: drbd5: self
F8152BAF51D9EACC:0000000000000000:4981B7129527F32B:0000000000000006
Oct  4 03:38:12 node0 kernel: drbd5: peer
015A3BE2ED294C8D:F8152BAF51D9EACD:4981B7129527F32A:0000000000000006
Oct  4 03:38:12 node0 kernel: drbd5: uuid_compare()=-1 by rule 5
Oct  4 03:38:12 node0 kernel: drbd5: peer( Unknown -> Primary ) conn(
WFReportParams -> WFBitMapT ) pdsk( DUnknown -> UpToDate )
Oct  4 03:38:12 node0 kernel: drbd5: Writing meta data super block now.
Oct  4 03:38:12 node0 kernel: drbd5: conn( WFBitMapT -> WFSyncUUID )
Oct  4 03:38:12 node0 kernel: drbd5:  uuid[Current] now 7C1CB159A4E77906
Oct  4 03:38:12 node0 kernel: drbd5:  uuid[Bitmap] now 0000000000000000
Oct  4 03:38:13 node0 kernel: drbd5: conn( WFSyncUUID -> SyncTarget )
disk( UpToDate -> Inconsistent )
Oct  4 03:38:14 node0 kernel: drbd16: aftr_isp( 0 -> 1 )
Oct  4 03:38:17 node0 kernel: drbd5: Began resync as SyncTarget (will
sync 1444 KB [361 bits set]).
Oct  4 03:38:17 node0 kernel: drbd5: Writing meta data super block now.
Oct  4 03:38:17 node0 kernel: drbd16: conn( StandAlone -> Unconnected )
Oct  4 03:38:17 node0 kernel: drbd16: receiver (re)started
Oct  4 03:38:17 node0 kernel: drbd16: conn( Unconnected -> WFConnection
)
Oct  4 03:38:17 node0 kernel: drbd16: conn( WFConnection ->
WFReportParams )
Oct  4 03:38:17 node0 kernel: drbd16: Handshake successful: DRBD Network
Protocol version 86
Oct  4 03:38:17 node0 kernel: drbd16: Writing meta data super block now.
Oct  4 03:38:17 node0 kernel: drbd5: Resync done (total 1 sec; paused 0
sec; 1444 K/sec)
Oct  4 03:38:17 node0 kernel: drbd5:  uuid[Bitmap] now F8152BAF51D9EACD
Oct  4 03:38:17 node0 kernel: drbd5:  uuid[History_start] now
4981B7129527F32A
Oct  4 03:38:17 node0 kernel: drbd5:  uuid[History_end] now
0000000000000006
Oct  4 03:38:17 node0 kernel: drbd5:  uuid[History_start] now
F8152BAF51D9EACD
Oct  4 03:38:17 node0 kernel: drbd5:  uuid[Bitmap] now 7C1CB159A4E77906
Oct  4 03:38:18 node0 kernel: drbd5:  uuid[Current] now 015A3BE2ED294C8C
Oct  4 03:38:18 node0 kernel: drbd5:  uuid[History_start] now
7C1CB159A4E77906
Oct  4 03:38:18 node0 kernel: drbd5:  uuid[Bitmap] now 0000000000000000
Oct  4 03:38:18 node0 kernel: drbd5: conn( SyncTarget -> Connected )
disk( Inconsistent -> UpToDate )
Oct  4 03:38:18 node0 kernel: drbd16: aftr_isp( 1 -> 0 )
Oct  4 03:38:20 node0 kernel: drbd5: Writing meta data super block now.
Oct  4 03:38:20 node0 kernel: drbd16: writing of bitmap took 1 jiffies
Oct  4 03:38:20 node0 kernel: drbd16: 4095 MB marked out-of-sync by on
disk bit-map.
Oct  4 03:38:20 node0 kernel: drbd16: 4194140 KB now marked out-of-sync
by on disk bit-map.
Oct  4 03:38:20 node0 kernel: drbd16: Writing meta data super block now.
Oct  4 03:38:20 node0 kernel: drbd16: peer( Unknown -> Primary ) conn(
WFReportParams -> WFBitMapT ) pdsk( DUnknown -> UpToDate ) peer_isp( 0
-> 1 )
Oct  4 03:38:21 node0 kernel: drbd16: Writing meta data super block now.
Oct  4 03:38:21 node0 kernel: drbd16: conn( WFBitMapT -> WFSyncUUID )
Oct  4 03:38:21 node0 kernel: drbd16: conn( WFSyncUUID -> PausedSyncT )
disk( UpToDate -> Inconsistent )
Oct  4 03:38:21 node0 kernel: drbd16: Began resync as PausedSyncT (will
sync 4194140 KB [1048535 bits set]).
Oct  4 03:38:21 node0 kernel: drbd16: Writing meta data super block now.


==============================Node1=========

Oct  4 03:38:11 node1 kernel: drbd5: Handshake successful: DRBD Network
Protocol version 86
Oct  4 03:38:11 node1 kernel: drbd5: drbd_sync_handshake:
Oct  4 03:38:11 node1 kernel: drbd5: self
015A3BE2ED294C8D:F8152BAF51D9EACD:4981B7129527F32A:0000000000000006
Oct  4 03:38:11 node1 kernel: drbd5: peer
F8152BAF51D9EACC:0000000000000000:4981B7129527F32B:0000000000000006
Oct  4 03:38:11 node1 kernel: drbd5: uuid_compare()=1 by rule 7
Oct  4 03:38:11 node1 kernel: drbd5: peer( Unknown -> Secondary ) conn(
WFReportParams -> WFBitMapS ) pdsk( DUnknown -> UpToDate )
Oct  4 03:38:11 node1 kernel: drbd5: Writing meta data super block now.
Oct  4 03:38:11 node1 kernel: drbd5:  uuid[History_start] now
F8152BAF51D9EACD
Oct  4 03:38:11 node1 kernel: drbd5:  uuid[Bitmap] now 7C1CB159A4E77906
Oct  4 03:38:11 node1 kernel: drbd5: conn( WFBitMapS -> SyncSource )
pdsk( UpToDate -> Inconsistent )
Oct  4 03:38:11 node1 kernel: drbd16: aftr_isp( 0 -> 1 )
Oct  4 03:38:13 node1 kernel: drbd5: Began resync as SyncSource (will
sync 1444 KB [361 bits set]).
Oct  4 03:38:13 node1 kernel: drbd5: Writing meta data super block now.
Oct  4 03:38:13 node1 kernel: drbd16: conn( WFConnection ->
WFReportParams )
Oct  4 03:38:13 node1 kernel: drbd16: Handshake successful: DRBD Network
Protocol version 86
Oct  4 03:38:13 node1 kernel: drbd16: Writing meta data super block now.
Oct  4 03:38:13 node1 kernel: drbd5: Resync done (total 1 sec; paused 0
sec; 1444 K/sec)
Oct  4 03:38:13 node1 kernel: drbd5:  uuid[History_start] now
7C1CB159A4E77906
Oct  4 03:38:13 node1 kernel: drbd5:  uuid[Bitmap] now 0000000000000000
Oct  4 03:38:13 node1 kernel: drbd5: conn( SyncSource -> Connected )
pdsk( Inconsistent -> UpToDate )
Oct  4 03:38:13 node1 kernel: drbd16: aftr_isp( 1 -> 0 )
Oct  4 03:38:15 node1 kernel: drbd5: Writing meta data super block now.
Oct  4 03:38:15 node1 kernel: drbd16: writing of bitmap took 1 jiffies
Oct  4 03:38:15 node1 kernel: drbd16: 4095 MB marked out-of-sync by on
disk bit-map.
Oct  4 03:38:15 node1 kernel: drbd16: 4194140 KB now marked out-of-sync
by on disk bit-map.
Oct  4 03:38:16 node1 kernel: drbd16: Writing meta data super block now.
Oct  4 03:38:16 node1 kernel: drbd16: peer( Unknown -> Secondary ) conn(
WFReportParams -> WFBitMapS ) pdsk( DUnknown -> UpToDate ) peer_isp( 0
-> 1 )
Oct  4 03:38:18 node1 kernel: drbd16: Writing meta data super block now.
Oct  4 03:38:18 node1 kernel: drbd16: conn( WFBitMapS -> PausedSyncS )
pdsk( UpToDate -> Inconsistent )
Oct  4 03:38:18 node1 kernel: drbd16: Began resync as PausedSyncS (will
sync 4194140 KB [1048535 bits set]).
Oct  4 03:38:18 node1 kernel: drbd16: Writing meta data super block now.

[-- Attachment #1.2: Type: text/html, Size: 19684 bytes --]

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

Index: drbd/drbd_main.c
===================================================================
--- drbd/drbd_main.c	(revision 19381)
+++ drbd/drbd_main.c	(working copy)
@@ -955,7 +955,7 @@
 	}
 
 	/* We want to pause/continue resync, tell peer. */
-	if ( ns.conn >= Connected && 
+	if ( ns.conn >= WFReportParams && 
 	     (( os.aftr_isp != ns.aftr_isp ) ||
 	      ( os.user_isp != ns.user_isp )) ) {
 		drbd_send_state(mdev);

Re: [Drbd-dev] DRBD8: nodes deadlock in PausedSync{ST]

[Philipp Reisner]

On Monday 29 October 2007 23:33:29 Montrose, Ernest wrote:
> Hi all,
> I have been struggling with a problem here where the nodes enter
> PausedSync[T|S] and stay there.
> This happens when one node come up from a fresh attach, connect
> sequence.  I think the issue happens this way. Say we have two volumes
> drbd5 and drbd16 and we attempt to connect both of them at roughly the
> same time.  Futhermore, drbd5 and 16 will require syncing say as sync
> target. What I observe is this:
> *	drbd16 is connecting and drbd5 is syncing. So 16 is paused isp=1
> *	drbd16 enters receive_state() but before acquiring the req_lock
> that thread loses the CPU to drbd5 that is finishing syncing.  After_isp
> is cleared on 16 giving drbd16 the green light to continue syncing. So
> far so good.
> *	Now drbd16 resumes with the old peer_isp=1
> *	So now we are paused forever.
>
> So I think receive_state() is just racy but I could be wrong. I am
> really not sure how to fix this but I include a patch here that may help
> to at least illustrate the problem. It seems close window for this
> particular race somewhat.
>

Hi Ernest,

You patch fixes the issue.

I spent an hour or so to understanding the exact timing, and drew 
diagrams of it... it is fixed with that change. No race left, I think.

I committed it to my git tree.

-Phil
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Vivenotgasse 48, 1120 Vienna, Austria        http://www.linbit.com :

RE: [Drbd-dev] DRBD8: nodes deadlock in PausedSync{ST]

[Montrose, Ernest]

Phil,
Thanks! I will test it all and let you know of any issues.

EM--

-----Original Message-----
From: Philipp Reisner [mailto:philipp.reisner@linbit.com] 
Sent: Wednesday, October 31, 2007 9:47 AM
To: drbd-dev@linbit.com
Cc: Montrose, Ernest
Subject: Re: [Drbd-dev] DRBD8: nodes deadlock in PausedSync{ST]

On Monday 29 October 2007 23:33:29 Montrose, Ernest wrote:
> Hi all,
> I have been struggling with a problem here where the nodes enter
> PausedSync[T|S] and stay there.
> This happens when one node come up from a fresh attach, connect
> sequence.  I think the issue happens this way. Say we have two volumes
> drbd5 and drbd16 and we attempt to connect both of them at roughly the
> same time.  Futhermore, drbd5 and 16 will require syncing say as sync
> target. What I observe is this:
> *	drbd16 is connecting and drbd5 is syncing. So 16 is paused isp=1
> *	drbd16 enters receive_state() but before acquiring the req_lock
> that thread loses the CPU to drbd5 that is finishing syncing.
After_isp
> is cleared on 16 giving drbd16 the green light to continue syncing. So
> far so good.
> *	Now drbd16 resumes with the old peer_isp=1
> *	So now we are paused forever.
>
> So I think receive_state() is just racy but I could be wrong. I am
> really not sure how to fix this but I include a patch here that may
help
> to at least illustrate the problem. It seems close window for this
> particular race somewhat.
>

Hi Ernest,

You patch fixes the issue.

I spent an hour or so to understanding the exact timing, and drew 
diagrams of it... it is fixed with that change. No race left, I think.

I committed it to my git tree.

-Phil
-- 
: Dipl-Ing Philipp Reisner                      Tel +43-1-8178292-50 :
: LINBIT Information Technologies GmbH          Fax +43-1-8178292-82 :
: Vivenotgasse 48, 1120 Vienna, Austria        http://www.linbit.com :