RE: [Drbd-dev] Barrier assert failures with latest 8.0 sources

RE: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Graham, Simon]

> I'm attempting to run with the latest 8.0 sources from Git (plus a
> couple of patches - basically the ones I have submitted that have not
> yet been applied) and am seeing a lot of assert failures in the
barrier
> code since the latest change to send barriers as early as possible. A
> representative trace for a device is attached - you will see that the
> device gets connected then pauses resync (not sure if this is really
> relevant) and then we start streaming the assert failures --
apparently
> we are off by one barrier from this point on...

Hmm.. maybe not as hard to diagnose as I thought -- when the drbd
connection is lost, we end up calling tl_clear which clears out the
transfer list _but_ leaves a single barrier in the list with number 4711
and req-cnt 0 (so oldest_barrier and newest_barrier both point to this
pseudo-barrier entry). 

When we reconnect and start processing requests again, when the first
barrier is needed, it will be number 4712 and will get added to the list
and the BarrierRq will be sent with this number. When the BarrierAck is
received, oldest_barrier is still 4711 though, leading to the assert
failure...

I'm not sure why tl_clear leaves this pseudo-barrier in the list...
shouldn't it simply leave the list completely empty just like tl_init
does?

Simon

Re: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Lars Ellenberg]

On Sat, Jan 19, 2008 at 11:40:35AM -0500, Graham, Simon wrote:
> > I'm attempting to run with the latest 8.0 sources from Git (plus a
> > couple of patches - basically the ones I have submitted that have not
> > yet been applied) and am seeing a lot of assert failures in the
> barrier
> > code since the latest change to send barriers as early as possible. A
> > representative trace for a device is attached - you will see that the
> > device gets connected then pauses resync (not sure if this is really
> > relevant) and then we start streaming the assert failures --
> apparently
> > we are off by one barrier from this point on...
> 
> Hmm.. maybe not as hard to diagnose as I thought -- when the drbd
> connection is lost, we end up calling tl_clear which clears out the
> transfer list _but_ leaves a single barrier in the list with number 4711
> and req-cnt 0 (so oldest_barrier and newest_barrier both point to this
> pseudo-barrier entry). 
> 
> When we reconnect and start processing requests again, when the first
> barrier is needed, it will be number 4712 and will get added to the list
> and the BarrierRq will be sent with this number. When the BarrierAck is
> received, oldest_barrier is still 4711 though, leading to the assert
> failure...
> 
> I'm not sure why tl_clear leaves this pseudo-barrier in the list...
> shouldn't it simply leave the list completely empty just like tl_init
> does?

probably.
we have seen these ASSERTS, too, btw, also without this latest change in
the barrier code, so aparently it has been there all along.
unfortunately we are all sort of distracted right now.
but coding will resume shortly :)

-- 
: Lars Ellenberg                            Tel +43-1-8178292-55 :
: LINBIT Information Technologies GmbH      Fax +43-1-8178292-82 :
: Vivenotgasse 48, A-1120 Vienna/Europe    http://www.linbit.com :

RE: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Graham, Simon]

> > I'm not sure why tl_clear leaves this pseudo-barrier in the list...
> > shouldn't it simply leave the list completely empty just like
tl_init
> > does?
> 
> probably.
> we have seen these ASSERTS, too, btw, also without this latest change
> in
> the barrier code, so aparently it has been there all along.
> unfortunately we are all sort of distracted right now.
> but coding will resume shortly :)

Well, I realize now that I completely misunderstood again;
newest_barrier represents thenext barrier that will be sent, so of
course there has to be one in the list at all times (and tl_init also
sets up barrier 4711).

I think the problem is that tl_clear does NOT clear the CREATE_BARRIER
bit from mdev->flags - so if we disconnect in the small window between
setting this bit and creating the new barrier, then when we reconnect
and send the first request, we'll end up creating a new barrier before
sending the BarrierRq(4711) (processing the first request that has to go
remote) and I think this gets us into the cycle of always being one
barrier behind the remote system... this would also explain why the
assert is intermittent since you have to disconnect in a small window...

Seem reasonable?
/simgr

Re: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Lars Ellenberg]

On Mon, Jan 21, 2008 at 09:29:02PM -0500, Graham, Simon wrote:
> > > I'm not sure why tl_clear leaves this pseudo-barrier in the list...
> > > shouldn't it simply leave the list completely empty just like
> tl_init
> > > does?
> > 
> > probably.
> > we have seen these ASSERTS, too, btw, also without this latest change
> > in
> > the barrier code, so aparently it has been there all along.
> > unfortunately we are all sort of distracted right now.
> > but coding will resume shortly :)
> 
> Well, I realize now that I completely misunderstood again;
> newest_barrier represents thenext barrier that will be sent, so of
> course there has to be one in the list at all times (and tl_init also
> sets up barrier 4711).
> 
> I think the problem is that tl_clear does NOT clear the CREATE_BARRIER
> bit from mdev->flags - so if we disconnect in the small window between
> setting this bit and creating the new barrier, then when we reconnect
> and send the first request, we'll end up creating a new barrier before
> sending the BarrierRq(4711) (processing the first request that has to go
> remote) and I think this gets us into the cycle of always being one
> barrier behind the remote system... this would also explain why the
> assert is intermittent since you have to disconnect in a small window...
> 
> Seem reasonable?

absolutely.

 :)

-- 
: Lars Ellenberg                            Tel +43-1-8178292-55 :
: LINBIT Information Technologies GmbH      Fax +43-1-8178292-82 :
: Vivenotgasse 48, A-1120 Vienna/Europe    http://www.linbit.com :

RE: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Graham, Simon]

> > I think the problem is that tl_clear does NOT clear the
> CREATE_BARRIER
> > bit from mdev->flags - so if we disconnect in the small window
> between
> > setting this bit and creating the new barrier, then when we
reconnect
> > and send the first request, we'll end up creating a new barrier
> before
> > sending the BarrierRq(4711) (processing the first request that has
to
> go
> > remote) and I think this gets us into the cycle of always being one
> > barrier behind the remote system... this would also explain why the
> > assert is intermittent since you have to disconnect in a small
> window...
> >
> > Seem reasonable?
> 
> absolutely.
> 
>  :)

Reasonable - yes, correct - no ;-(

Clearing the bit in tl_clear didn't work so I dug some more and I think
I _really_ found it this time...

In _about_to_complete_local_write, we see this code:

	/* before we can signal completion to the upper layers,
	 * we may need to close the current epoch */
	if (req->epoch == mdev->newest_barrier->br_number)
		queue_barrier(mdev);

This can be true when the connection is not active _if_ the connection
is torn down before the first I/O completes (seems a little unlikely,
but possible) - in that case, the req->epoch will be 4711 and the
disconnect cleared out the list so that newest_barrier->br_number is
4711... so we go ahead and call queue_barrier() which sets the
CREATE_BARRIER bit...

I think this will also result in inc_ap_pending() being called with no
matching decrement - when the worker thread runs w_send_barrier, it will
detect that the conn state is < Connected and bail without decrementing
the count...

I do feel that the situations when this can arise should be incredibly
rare - the connection has to fail between issuing the first request and
the time it completes... and yet I can hit this problem fairly easily,
so maybe there is some other situation I haven't thought of that causes
this path to be taken.

Anyway - presumably the fix is to modify
_about_to_complete_local_write() to not do the barrier stuff unless the
connection state is >= Connected?

Simon

RE: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Graham, Simon]

> I do feel that the situations when this can arise should be incredibly
> rare - the connection has to fail between issuing the first request
and
> the time it completes... and yet I can hit this problem fairly easily,
> so maybe there is some other situation I haven't thought of that
causes
> this path to be taken.
> 

So, I was right to be concerned -- the _actual_ cause of the problem is
as follows:

1. tl_clear first runs through the TL and does a
req_mod(connection_lost)
   This _can_ cause requests to be completed and therefore can end up
   calling queue_barrier because this is the first request in the
current
   barrier. This means that CREATE_BARRIER can be set in the flags.

2. Then tl_clear reinitializes the transfer list but does not clear the
flag.

Thus pretty much anytime you lose the connection whilst there is traffic
in progress you run the risk of setting the flag and thereby setting
yourself up to create a new barrier incorrectly next time you connect.

I think the fixes are:

a. Don't do queue_barrier if the connection state is <Connected
b. Make sure the flag is clear in drbd_connect
c. Modify w_send_barrier to decrement the ap count if it decides to not
   send a barrier (e.g. if the connection is lost between the time the
   work item is queued and the time it runs).

Will submit patch once I've tested this...
Simon

RE: [Drbd-dev] Barrier assert failures with latest 8.0 sources

[Graham, Simon]

> I think the fixes are:
> 
> a. Don't do queue_barrier if the connection state is <Connected
> b. Make sure the flag is clear in drbd_connect
> c. Modify w_send_barrier to decrement the ap count if it decides to
not
>    send a barrier (e.g. if the connection is lost between the time the
>    work item is queued and the time it runs).
> 

Scratch item c) -- tl_clear already does this...
/simgr

[Drbd-dev] Barrier assert failures with latest 8.0 sources

[Graham, Simon]

Hi,

I'm attempting to run with the latest 8.0 sources from Git (plus a
couple of patches - basically the ones I have submitted that have not
yet been applied) and am seeing a lot of assert failures in the barrier
code since the latest change to send barriers as early as possible. A
representative trace for a device is attached - you will see that the
device gets connected then pauses resync (not sure if this is really
relevant) and then we start streaming the assert failures -- apparently
we are off by one barrier from this point on...

Any suggestions?
Simon

   5270:Jan 19 00:15:43 node1 kernel: drbd5: conn( Unconnected ->
WFConnection ) 
   6214:Jan 19 00:34:45 node1 kernel: drbd5: Handshake successful: DRBD
Network Protocol version 86
   6216:Jan 19 00:34:46 node1 kernel: drbd5: conn( WFConnection ->
WFReportParams ) 
   6219:Jan 19 00:34:46 node1 kernel: drbd5: Starting asender thread
(from drbd5_receiver [15383])
   6221:Jan 19 00:34:47 node1 kernel: drbd5: drbd_sync_handshake:
   6222:Jan 19 00:34:48 node1 kernel: drbd5: self
0D17E6C6F3714F2F:E0FEF0615D2424EF:2953DE3A10384390:169A43D80FC7A631
   6224:Jan 19 00:34:48 node1 kernel: drbd5: peer
0000000000000004:0000000000000000:0000000000000000:0000000000000000
   6226:Jan 19 00:34:49 node1 kernel: drbd5: uuid_compare()=2 by rule 3
   6228:Jan 19 00:34:50 node1 kernel: drbd5: Becoming sync source due to
disk states.
   6231:Jan 19 00:34:51 node1 kernel: drbd5: Writing meta data super
block now.
   6234:Jan 19 00:34:53 node1 kernel: drbd5: writing of bitmap took 0
jiffies
   6237:Jan 19 00:34:53 node1 kernel: drbd5: 1023 MB (262127 bits)
marked out-of-sync by on disk bit-map.
   6240:Jan 19 00:34:54 node1 kernel: drbd5: Writing meta data super
block now.
   6246:Jan 19 00:35:04 node1 kernel: drbd5: peer( Unknown -> Secondary
) conn( WFReportParams -> WFBitMapS ) pdsk( DUnknown -> Inconsistent ) 
   6251:Jan 19 00:35:14 node1 kernel: drbd5: Writing meta data super
block now.
   6257:Jan 19 00:35:19 node1 kernel: drbd5:  uuid[History_start] now
E0FEF0615D2424EF
   6261:Jan 19 00:35:23 node1 kernel: drbd5:  uuid[Bitmap] now
BF161CBD2512E46A
   6264:Jan 19 00:35:28 node1 kernel: drbd5: conn( WFBitMapS ->
SyncSource ) 
   6279:Jan 19 00:35:53 node1 kernel: drbd5: Began resync as SyncSource
(will sync 1048508 KB [262127 bits set]).
   6281:Jan 19 00:35:56 node1 kernel: drbd5: Writing meta data super
block now.
   6290:Jan 19 00:36:07 node1 kernel: drbd5: conn( SyncSource ->
PausedSyncS ) aftr_isp( 0 -> 1 ) 
   6292:Jan 19 00:36:08 node1 kernel: drbd5: Resync suspended
   6303:Jan 19 00:36:23 node1 kernel: drbd5: peer_isp( 0 -> 1 ) 
   6308:Jan 19 00:36:25 node1 kernel: drbd5: ASSERT( b->br_number ==
barrier_nr ) in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:240
   6311:Jan 19 00:36:27 node1 kernel: drbd5: ASSERT( b->n_req ==
set_size ) in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:241
   6314:Jan 19 00:36:28 node1 kernel: drbd5: b->br_number = 4711 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:245
   6318:Jan 19 00:36:29 node1 kernel: drbd5: barrier_nr = 4712 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:246
   6322:Jan 19 00:36:30 node1 kernel: drbd5: b->n_req = 0 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:249
   6326:Jan 19 00:36:31 node1 kernel: drbd5: set_size = 1 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:250
   6334:Jan 19 00:36:37 node1 kernel: drbd5: ASSERT( b->br_number ==
barrier_nr ) in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:240
   6337:Jan 19 00:36:38 node1 kernel: drbd5: b->br_number = 4712 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:245
   6340:Jan 19 00:36:38 node1 kernel: drbd5: barrier_nr = 4713 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:246
   6343:Jan 19 00:36:39 node1 kernel: drbd5: ASSERT( b->br_number ==
barrier_nr ) in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:240
   6347:Jan 19 00:36:40 node1 kernel: drbd5: ASSERT( b->n_req ==
set_size ) in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:241
   6350:Jan 19 00:36:42 node1 kernel: drbd5: b->br_number = 4713 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:245
   6353:Jan 19 00:36:43 node1 kernel: drbd5: barrier_nr = 4714 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:246
   6356:Jan 19 00:36:43 node1 kernel: drbd5: b->n_req = 1 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUIn_req = 1 in
/sandbox/sgraham/sn/drbd-git/platform/drbd/src/dist/BUILD/drbd-8.0.8/drb
d/drbd_main.c:249