Fix deadlock in discard stats #1070

ashish-goswami · 2019-10-07T15:56:39Z

This change is

pullrequest

✅ A review job has been created and sent to the PullRequest network.

@ashish-goswami you can click here to see the review status or cancel the code review job.

coveralls · 2019-10-07T16:11:52Z

Coverage increased (+0.1%) to 77.676% when pulling ecadd42 on ashish/discardstats-deadlock into f50343f on master.

pullrequest

Can you add in the commit details, why there was a deadlock? It would be much clearer than just the code changes.

Reviewed with ❤️ by PullRequest

pullrequest · 2019-10-07T22:27:01Z

value_test.go

+	// Here insert discardStats more than the cap(vlog.lfDiscardStats.flushChan), that will ensure
+	// if we have tried to write at least one discard stats entry while writes were blocked.
+	encodedDS := db.vlog.encodedDiscardStats()
+	for i := 0; i < cap(db.vlog.lfDiscardStats.flushChan)+2; i++ {


Why 2 here?

pullrequest · 2019-10-07T22:27:01Z

value.go

+		encodedDS := vlog.encodedDiscardStats()
+		vlog.lfDiscardStats.flushChan <- encodedDS
+	}
+	vlog.lfDiscardStats.Unlock()


It's a good idea to to defer vlog.lfDiscardStats.Unlock() right after you lock. That way, if anything happens within the critical section of your code (unhandled errors), then you will at least unlock and prevent a deadlock.

pullrequest · 2019-10-07T22:27:01Z

db.go

-		return errors.Wrap(err, "failed to flush discard stats")
-	}
+	// Before closing writes, stop flushing discardStats.
+	db.vlog.closeFlushDiscardStats()


Does this no longer return an error?

pullrequest · 2019-10-07T22:27:01Z

value.go

-	} else if err != nil {
-		return errors.Wrapf(err, "failed to push discard stats to write channel")
+
+LOOP:


Great idea to provide labels 👍

pullrequest

valueLog is a very large file, and could use some refactoring. I saw that there is a lot of logic that has to do with lfDiscardStats. This should definitely be in its own file and interface.

Reviewed with ❤️ by PullRequest

pullrequest · 2019-10-08T00:44:41Z

value.go

+		}}
+		req, err := vlog.db.sendToWriteCh(entries)
+		if err == ErrBlockedWrites {
+			// We'll block write while closing db. When L0 compaction in close may push discard


grammar nit: writes instead of write.
I think this line needs some clarification: "When L0 compaction in close may push discard"

pullrequest · 2019-10-08T00:44:41Z

value.go

-// This will be called while storing stats in BadgerDB
-// caller should acquire lock before encoding the stats.
+// encodedDiscardStats returns []byte representation of lfDiscardStats. This will be called while
+// storing stats in BadgerDB caller should acquire lock before encoding the stats.
 func (vlog *valueLog) encodedDiscardStats() []byte {


Same as above, this should be part of the lfDiscardStats interface.

pullrequest · 2019-10-08T00:44:41Z

value.go


-	if len(vlog.lfDiscardStats.m) == 0 {
-		return nil
+	process := func(ds []byte) error {


encodedDiscardedStats or encodedDS would be better than ds.
Code is read much more often than it is written, it would be much more intuitive to be more descriptive.

pullrequest · 2019-10-08T00:44:41Z

value.go

+		select {
+		case <-vlog.lfDiscardStats.closer.HasBeenClosed():
+			vlog.lfDiscardStats.Lock()
+			vlog.lfDiscardStats.flushChanClosed = true


to prevent scattering Lock and Unlock everywhere, it would be better to have lfDiscardedStats have a CloseFlushChan function.

func (ds *DiscardStats) CloseFlushChan() { ds.Lock() defer ds.Unlock() close(ds.flushChan) ds.flushChanClosed = true }

pullrequest · 2019-10-08T00:44:42Z

value.go

+	}
+}
+
+func (vlog *valueLog) closeFlushDiscardStats() {


this is just using lfDiscardStat APIs, and doesn't have any valueLog internal logic. Push this into the lfDiscardStat interface.

pullrequest · 2019-10-08T00:44:42Z

value.go

-		vlog.lfDiscardStats.Unlock()
-		// flushDiscardStats also acquires lock. So, we need to unlock here.
-		return vlog.flushDiscardStats()
+		encodedDS := vlog.encodedDiscardStats()


since you only use this once, we can just incorporate it with the line below:
vlog.lfDiscardStats.flushChan <- vlog.encodedDiscardStats():

pullrequest · 2019-10-08T00:44:42Z

value_test.go

-	}
-	// This is important. Set updateSinceFlush to discardStatsFlushThresold so
+	db.vlog.lfDiscardStats.m = map[uint32]int64{0: 0}
+	// This is important. Set updateSinceFlush to discardStatsFlushThreshold so


Could we also add a test that replicates the deadlock, and make sure it does not deadlock with this change?

ashish-goswami

Reviewable status: 0 of 5 files reviewed, 11 unresolved discussions (waiting on @ashish-goswami, @balajijinnah, @jarifibrahim, @manishrjain, and @pullrequest[bot])

db.go, line 384 at r1 (raw file):

Previously, pullrequest[bot] wrote…

Does this no longer return an error?

No. This doesn't.

value.go, line 1697 at r1 (raw file):

Previously, pullrequest[bot] wrote…

since you only use this once, we can just incorporate it with the line below:
vlog.lfDiscardStats.flushChan <- vlog.encodedDiscardStats():

Done.

value.go, line 1711 at r1 (raw file):

Previously, pullrequest[bot] wrote…

encodedDiscardedStats or encodedDS would be better than ds.
Code is read much more often than it is written, it would be much more intuitive to be more descriptive.

Done.

value.go, line 1721 at r1 (raw file):

Previously, pullrequest[bot] wrote…

grammar nit: writes instead of write.
I think this line needs some clarification: "When L0 compaction in close may push discard"

Done.

value.go, line 1762 at r1 (raw file):

Previously, pullrequest[bot] wrote…

It's a good idea to to defer vlog.lfDiscardStats.Unlock() right after you lock. That way, if anything happens within the critical section of your code (unhandled errors), then you will at least unlock and prevent a deadlock.

Since this lock will be used after we signal to closer, we need to unlock it to avoid deadlock.

value_test.go, line 1111 at r1 (raw file):

Previously, pullrequest[bot] wrote…

Why 2 here?

This ensures that we are sending more that cap(db.vlog.lfDiscardStats.flushChan) to the chan.

poonai · 2019-10-09T10:36:37Z

LGTM. But, if we have flusher go routine in the db level. It fits well with the existing mechanism(all go routine are spined in the db.go).

Also, It'll easy to merge this change to the WAL and vlog separation.

jarifibrahim

This was a tough change. Thanks for fixing this @ashish-goswami . I've added some minor comments.

Reviewed 3 of 5 files at r1.
Dismissed @pullrequest[bot] from a discussion.
Reviewable status: 3 of 5 files reviewed, 13 unresolved discussions (waiting on @ashish-goswami, @balajijinnah, @jarifibrahim, @manishrjain, and @pullrequest[bot])

value.go, line 1721 at r1 (raw file):

Previously, ashish-goswami (Ashish Goswami) wrote…

Done.

This is not done. The comment "When L0 compaction in close may ..." doesn't make sense.
I think you mean "The L0 compaction in DB.Close() function might push discard stats..."

value.go, line 1735 at r1 (raw file):

Previously, pullrequest[bot] wrote…

to prevent scattering Lock and Unlock everywhere, it would be better to have lfDiscardedStats have a CloseFlushChan function.
func (ds *DiscardStats) CloseFlushChan() {
    ds.Lock()
    defer ds.Unlock()

    close(ds.flushChan)
    ds.flushChanClosed = true
}

This makes sense to me. We should have a separate closeFlushChan function. It would make code much cleaner as well.

value.go, line 1755 at r1 (raw file):

Previously, pullrequest[bot] wrote…

this is just using lfDiscardStat APIs, and doesn't have any valueLog internal logic. Push this into the lfDiscardStat interface.

@ashish-goswami We should do this. The encodedDiscardStats can also be added to lfDiscardStats interface.

value.go, line 1684 at r2 (raw file):

	defer vlog.lfDiscardStats.Unlock()

	// Compaction is closed after closing of flushing of discard stats.

// updateDiscardStats can be called by compaction after the `flushChan` is closed. This can happen when the DB is being closed.

value.go, line 1759 at r2 (raw file):

	if len(vlog.lfDiscardStats.m) > 0 {
		encodedDS := vlog.encodedDiscardStats()
		vlog.lfDiscardStats.flushChan <- encodedDS

This can also be written as

vlog.lfDiscardStats.flushChan <- vlog.encodedDiscardStats()

value_test.go, line 1127 at r1 (raw file):

Previously, pullrequest[bot] wrote…

Could we also add a test that replicates the deadlock, and make sure it does not deadlock with this change?

I am working

value_test.go, line 1109 at r2 (raw file):

	db.vlog.lfDiscardStats.m = map[uint32]int64{0: 0}
	db.blockWrite()
	// Here insert discardStats more than the cap(vlog.lfDiscardStats.flushChan), that will ensure

Push discard stats more than the capacity of flushChan. This ensures at least one flush operation completes successfully after the writes were blocked.

jarifibrahim

Reviewable status: 3 of 5 files reviewed, 13 unresolved discussions (waiting on @ashish-goswami, @balajijinnah, @manishrjain, and @pullrequest[bot])

value_test.go, line 1127 at r1 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

I am working

I am trying to write a test for this.

ashish-goswami

Reviewable status: 2 of 5 files reviewed, 13 unresolved discussions (waiting on @ashish-goswami, @balajijinnah, @jarifibrahim, @manishrjain, and @pullrequest[bot])

value.go, line 1721 at r1 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

This is not done. The comment "When L0 compaction in close may ..." doesn't make sense.
I think you mean "The L0 compaction in DB.Close() function might push discard stats..."

updated the comment.

value.go, line 1735 at r1 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

This makes sense to me. We should have a separate closeFlushChan function. It would make code much cleaner as well.

Not sure, if we should create new function for this.

value.go, line 1755 at r1 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

@ashish-goswami We should do this. The encodedDiscardStats can also be added to lfDiscardStats interface.

Thinking of raising anther PR for this.

value.go, line 1684 at r2 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

// updateDiscardStats can be called by compaction after the `flushChan` is closed. This can happen when the DB is being closed.

updated the comment.

value.go, line 1759 at r2 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

This can also be written as
vlog.lfDiscardStats.flushChan <- vlog.encodedDiscardStats()

Done.

value_test.go, line 1109 at r2 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

Push discard stats more than the capacity of flushChan. This ensures at least one flush operation completes successfully after the writes were blocked.

Done.

jarifibrahim

Dismissed @pullrequest[bot] from a discussion.
Reviewable status: 2 of 5 files reviewed, 9 unresolved discussions (waiting on @ashish-goswami, @balajijinnah, @jarifibrahim, @manishrjain, and @pullrequest[bot])

value.go, line 1755 at r1 (raw file):

Previously, ashish-goswami (Ashish Goswami) wrote…

Thinking of raising anther PR for this.

I feel it should be part of this PR itself. Why commit some code which we know needs refactoring?

value.go, line 1769 at r1 (raw file):

Previously, pullrequest[bot] wrote…

Same as above, this should be part of the lfDiscardStats interface.

I also think this should be part of the lfDiscardStats interface.

jarifibrahim

The changes look good to me but the PR needs a proper description.

Reviewed 3 of 3 files at r4.
Dismissed @pullrequest[bot] from 4 discussions.
Reviewable status: all files reviewed, 9 unresolved discussions (waiting on @ashish-goswami, @balajijinnah, @manishrjain, and @pullrequest[bot])

value.go, line 1704 at r4 (raw file):

		if vlog.lfDiscardStats.updatesSinceFlush > discardStatsFlushThreshold {
			encodedDS, _ = json.Marshal(vlog.lfDiscardStats.m)
			vlog.lfDiscardStats.updatesSinceFlush = 0

If the above json.Marshall(...) call fails, we'll still set updatesSinceFlush to 0 which is incorrect. We should skip setting updateSinceFlush to 0 if we weren't able to marshal the stats.

value_test.go, line 486 at r4 (raw file):

	// db.vlog.lfDiscardStats.updatesSinceFlush is already > discardStatsFlushThreshold,
	// send empty map to flushChan, so that latest discardStats map can be persited.

typo: persisted

value_test.go, line 488 at r4 (raw file):

	// send empty map to flushChan, so that latest discardStats map can be persited.
	db.vlog.lfDiscardStats.flushChan <- map[uint32]int64{}
	time.Sleep(1 * time.Second) // Wait to map to be persisted.

typo: wait for ...

value_test.go, line 1003 at r4 (raw file):

}

// // Regression test for https://github.com/dgraph-io/dgraph/issues/3669

This change is not necessary.

ashish-goswami

Dismissed @jarifibrahim and @pullrequest[bot] from 5 discussions.
Reviewable status: 3 of 5 files reviewed, 5 unresolved discussions (waiting on @balajijinnah, @jarifibrahim, @manishrjain, and @pullrequest[bot])

value.go, line 1704 at r4 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

If the above json.Marshall(...) call fails, we'll still set updatesSinceFlush to 0 which is incorrect. We should skip setting updateSinceFlush to 0 if we weren't able to marshal the stats.

Valid point. But I was thinking of why json.Marshal() will return error if our map is valid. Could not think of anything. Anyways now checking for it.

value_test.go, line 486 at r4 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

typo: persisted

Fixed.

value_test.go, line 488 at r4 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

typo: wait for ...

Done.

value_test.go, line 1003 at r4 (raw file):

Previously, jarifibrahim (Ibrahim Jarif) wrote…

This change is not necessary.

Fixed.

poonai

Minor comment. get approval from @jarifibrahim

Reviewable status: 3 of 5 files reviewed, 6 unresolved discussions (waiting on @ashish-goswami, @jarifibrahim, @manishrjain, and @pullrequest[bot])

value.go, line 1704 at r4 (raw file):

		if vlog.lfDiscardStats.updatesSinceFlush > discardStatsFlushThreshold {
			encodedDS, _ = json.Marshal(vlog.lfDiscardStats.m)
			vlog.lfDiscardStats.updatesSinceFlush = 0

Update the updatesSinceFlush after pushing to the sencCh successfully.

jarifibrahim

This PR needs a description.

Reviewable status: 3 of 5 files reviewed, 2 unresolved discussions (waiting on @ashish-goswami, @jarifibrahim, @manishrjain, and @pullrequest[bot])

manishrjain

Comments.

Reviewed 2 of 5 files at r1, 1 of 3 files at r4, 2 of 2 files at r5.
Reviewable status: all files reviewed, 7 unresolved discussions (waiting on @ashish-goswami and @pullrequest[bot])

value.go, line 1708 at r3 (raw file):

}

func (vlog *valueLog) startFlushDiscardStats() {

Keep the name the same.

value.go, line 1695 at r5 (raw file):

	mergeStats := func(stats map[uint32]int64) (encodedDS []byte) {
		vlog.lfDiscardStats.Lock()

Make this a RWLock. And this should acquire write lock. And readers should acquire read locks.

value.go, line 1704 at r5 (raw file):

		if vlog.lfDiscardStats.updatesSinceFlush > discardStatsFlushThreshold {
			var err error
			encodedDS, err = json.Marshal(vlog.lfDiscardStats.m)

Avoid this named return.

value.go, line 1714 at r5 (raw file):

	process := func(stats map[uint32]int64) error {
		encodedDS := mergeStats(stats)

This should return error.

value.go, line 1736 at r5 (raw file):

	for {
		select {
		case <-vlog.lfDiscardStats.closer.HasBeenClosed():

closer := vlog.lf.closer

ashish-goswami

Reviewable status: 3 of 5 files reviewed, 7 unresolved discussions (waiting on @ashish-goswami, @manishrjain, and @pullrequest[bot])

value.go, line 1695 at r5 (raw file):

Previously, manishrjain (Manish R Jain) wrote…

Make this a RWLock. And this should acquire write lock. And readers should acquire read locks.

Done.

value.go, line 1704 at r5 (raw file):

Previously, manishrjain (Manish R Jain) wrote…

Avoid this named return.

Done.

value.go, line 1714 at r5 (raw file):

Previously, manishrjain (Manish R Jain) wrote…

This should return error.

Done.

value.go, line 1736 at r5 (raw file):

Previously, manishrjain (Manish R Jain) wrote…

closer := vlog.lf.closer

Done.

connorgorman · 2019-10-23T19:16:46Z

@jarifibrahim Is the description of the deadlock in #1032 correct or was there a different issue at hand? This change is pretty complex so it's difficult to determine when this was introduced and what versions may be affected

jarifibrahim · 2019-10-23T19:51:10Z

Hey @connorgorman the description of issue #1032 was correct and this PR has fixed it.

When we perform compaction, we flush discard stats back into badger. These discard stats follow the same path as normal keys (memtable -> L0 -> L1 -> ... ). In the reported issue, compaction was triggered because L0 and memtable were full. When the compaction completed, it tried to push the discard stats back into the DB but since memtable was full, we could not push the entry into badger. This was causing the deadlock. It should have been fixed by this PR.

See c1cf0d7 for some more explanation.

If you're looking for when this issue was introduced, it was introduced in fa0679c .

Fixes #1032 Currently discardStats flow is as follows: * Discard Stats are generated during compaction. At the end, compaction routine updates these stats in vlog(vlog maintains all discard stats). If number of updates exceeds a threshold, a new request is generated and sent to write channel. Routine waits for request to complete(request.Wait()). * Requests are consumed from write channel and written to vlog first and then to memtable. * If memtable is full, it is flushed to flush channel. *From flush channel, memtables are written to L0 only if there are less than or equal to NumLevelZeroTablesStall tables already. Events which can lead to deadlock: Compaction is running on L0 which has NumLevelZeroTablesStall tables currently and tries to flush discard stats to write channel. After pushing stats to write channel, it waits for write request to complete, which cannot be completed due to cyclic dependency. Fix: This PR introduces a flush channel(buffered) for discardStats. Compaction routine, will push generated discard stats to flush channel, if channel is full it just returns. This decouples compaction and writes. We have a separate routine for consuming stats from flush chan. (cherry picked from commit c1cf0d7)

ashish-goswami added 2 commits October 7, 2019 14:31

Decouple compaction from flushing of discardStats

1496998

Fix breaking tests

5870c76

ashish-goswami requested a review from poonai October 7, 2019 15:56

ashish-goswami requested review from jarifibrahim, manishrjain and a team as code owners October 7, 2019 15:56

pullrequest bot reviewed Oct 7, 2019

View reviewed changes

pullrequest bot reviewed Oct 8, 2019

View reviewed changes

Fix races in vlog tests

34237a9

ashish-goswami commented Oct 9, 2019

View reviewed changes

jarifibrahim suggested changes Oct 10, 2019

View reviewed changes

jarifibrahim reviewed Oct 10, 2019

View reviewed changes

Address review comments

3a16d54

ashish-goswami commented Oct 10, 2019

View reviewed changes

jarifibrahim approved these changes Oct 10, 2019

View reviewed changes

ashish-goswami added 2 commits October 11, 2019 01:58

Simplify code for flushing DiscardStats

c8f0d4e

Fix race in discard tests

12cea56

jarifibrahim suggested changes Oct 14, 2019

View reviewed changes

Address review comments

054ac4e

ashish-goswami commented Oct 14, 2019

View reviewed changes

poonai approved these changes Oct 14, 2019

View reviewed changes

jarifibrahim approved these changes Oct 14, 2019

View reviewed changes

manishrjain approved these changes Oct 14, 2019

View reviewed changes

Address review comments

ecadd42

ashish-goswami commented Oct 14, 2019

View reviewed changes

ashish-goswami merged commit c1cf0d7 into master Oct 16, 2019

ashish-goswami deleted the ashish/discardstats-deadlock branch October 16, 2019 10:38

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix deadlock in discard stats #1070

Fix deadlock in discard stats #1070

ashish-goswami commented Oct 7, 2019 •

edited

Loading

pullrequest bot left a comment

coveralls commented Oct 7, 2019 •

edited

Loading

pullrequest bot left a comment

pullrequest bot Oct 7, 2019

pullrequest bot Oct 7, 2019

pullrequest bot Oct 7, 2019

pullrequest bot Oct 7, 2019

pullrequest bot left a comment

pullrequest bot Oct 8, 2019

pullrequest bot Oct 8, 2019

pullrequest bot Oct 8, 2019

pullrequest bot Oct 8, 2019

pullrequest bot Oct 8, 2019

pullrequest bot Oct 8, 2019

pullrequest bot Oct 8, 2019

ashish-goswami left a comment

poonai commented Oct 9, 2019

jarifibrahim left a comment

jarifibrahim left a comment

ashish-goswami left a comment

jarifibrahim left a comment

jarifibrahim left a comment

ashish-goswami left a comment

poonai left a comment

jarifibrahim left a comment

manishrjain left a comment

ashish-goswami left a comment

connorgorman commented Oct 23, 2019

jarifibrahim commented Oct 23, 2019

Fix deadlock in discard stats #1070

Fix deadlock in discard stats #1070

Conversation

ashish-goswami commented Oct 7, 2019 • edited Loading

pullrequest bot left a comment

Choose a reason for hiding this comment

coveralls commented Oct 7, 2019 • edited Loading

pullrequest bot left a comment

Choose a reason for hiding this comment

pullrequest bot Oct 7, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 7, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 7, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 7, 2019

Choose a reason for hiding this comment

pullrequest bot left a comment

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

pullrequest bot Oct 8, 2019

Choose a reason for hiding this comment

ashish-goswami left a comment

Choose a reason for hiding this comment

poonai commented Oct 9, 2019

jarifibrahim left a comment

Choose a reason for hiding this comment

jarifibrahim left a comment

Choose a reason for hiding this comment

ashish-goswami left a comment

Choose a reason for hiding this comment

jarifibrahim left a comment

Choose a reason for hiding this comment

jarifibrahim left a comment

Choose a reason for hiding this comment

ashish-goswami left a comment

Choose a reason for hiding this comment

poonai left a comment

Choose a reason for hiding this comment

jarifibrahim left a comment

Choose a reason for hiding this comment

manishrjain left a comment

Choose a reason for hiding this comment

ashish-goswami left a comment

Choose a reason for hiding this comment

connorgorman commented Oct 23, 2019

jarifibrahim commented Oct 23, 2019

ashish-goswami commented Oct 7, 2019 •

edited

Loading

coveralls commented Oct 7, 2019 •

edited

Loading