Badger: deadlock with two writing transactions

[guelfey]

What version of Go are you using (go version)?

$ go version
go version go1.10.2 linux/amd64

Cross-compiled for ARM, however.

What version of Badger are you using?

acce481eab83cd96f2d5470802f8f8ab8d793431

Does this issue reproduce with the latest master?

Not tried yet since it's hard to reproduce.

What are the hardware specifications of the machine (RAM, OS, Disk)?

ARM32, 1GB RAM, customized Linux (kernel 4.14), 4GB MMC Flash

What did you do?

General use of badger as a persistent cache - we have one goroutine that reads data from a channel and (blockingly) sends it to our backend, a second goroutine that tries to write to this channel, but writes the data to badger if the receiver is blocked, and a third goroutine that periodically checks if the badger DB is empty, and if not, deletes the entries from the DB and sends them back to the second goroutine via a channel.

What did you expect to see?

Normal operation without deadlocks.

What did you see instead?

In some cases, both goroutines that use badger calls get locked up waiting on badger-internal WaitGroups without any particular cause. A traceback of the relevant goroutines retrieved via SIGQUIT is attached.

deadlock-two-writes.log

[jarifibrahim]

Hey @guelfey, do you have more badger logs? It could be possible that your writes are blocked because of either

1. The drop operation or
2. The writes are stalled.

Badger logs might have some more information about what was going on.

[guelfey]

Hi @jarifibrahim,

we sadly don't have any further logs right now as this issue only comes up rarely, and in the one case where we were able to get the trace, there were no additional logs. We'll enable the event logging and see if we can get more logs related to the issue. But I can already tell you that we don't use Drop at all and the writes shouldn't be stalled by other reads - only the two goroutines I mentioned and which are also listed in the traceback do any kind of calls to Badger functions.

[guelfey]

Hi @jarifibrahim,

we were able to reproduce this issue, this time including event logging. Both a trace of relevant goroutines and the event log (the text of /debug/events when fully expanded) just before getting the trace are attached. Assuming the times in the log are in UTC, our application goroutines were blocked since 7:07, and the logs and trace were taken around 7:47.

badger-deadlock-231.log

badger-log-231.log

[guelfey]

Hi @jarifibrahim,

I started to dig a bit more into the logs and the code of badger itself. What I gathered so far is:

• writes are stalled because db.mt is full, but nobody is reading from flushChan (https://github.com/dgraph-io/badger/blob/acce481eab83cd96f2d5470802f8f8ab8d793431/db.go#L756)
• flushMemtable is blocked in addLevel0Table as L0 or L1 are compactable.
• One compaction worker is currently running seemingly normally. Unfortunately, because I only saved the event log for the "Badger" prefix, but the compaction workers use a different one, I don't have any information on what exactly was going on in the compaction, but I suspect it was stuck in an infinite loop somehow. I'll see if I can reproduce the issue and then get compaction logs also. In the meatime, maybe you already have an idea what could cause this behaviour for the compaction?

[guelfey]

Hi @jarifibrahim,

we observed this issue once again. This time, I also looked at /debug/requests and saw badger repeatedly tries to do a L0 compaction, but fails everytime with the same error:

    LOG Compact FAILED with error: MANIFEST removes non-existing table 14: {elog:0x114b6c60 thisLevel:0x114a9680 nextLevel:0x114a96d0 top:[0x12b22090 0x114879e0 0x11c8c120 0x115b8480 0x1145b440 0x1145a1b0 0x115b83f0 0x13c063f0 0x12b22120 0x12b221b0] bot:[0x1377c120 0x115b8360] thisRange:{left:[] right:[] inf:true} nextRange:{left:[1 113 56 157 108 111 132 0 223 12 92 114 103 53 102 148 0 0 0 0 0 0 0 0] right:[33 98 97 100 103 101 114 33 104 101 97 100 255 255 255 255 255 255 255 255] inf:false} thisSize:0}

I took a copy of the database after stopping the application. Table 14 is the first L0 table and present both in the MANIFEST file and as an .sst on disk. I suspect this is due to an earlier compaction failing after the in-memory manifest was already modified, but before writing it back to disk. But I don't have any information on what this initial error might be because the event log only shows the last few compactions. We're anyway updating to badger v1.6.1 where this logging output is made configurable, so we'll save it persistently to get to the root of this issue.

[jarifibrahim]

This issue is related to https://github.com/dgraph-io/badger/issues/1283 . In https://github.com/dgraph-io/badger/issues/1283, write batch is used which internally uses multiple transactions.

[jarifibrahim]

@guelfey Can you try to run your code on v2.0.2? I noticed that tissue #1283 was not reproducible on the latest master (or v2.0.3). Meanwhile, I'll try to figure out what's going on.

[guelfey]

I don't think that will be possible easily - I still don't have a specific test case that triggers this behaviour, so we're right now basically waiting for it to happen in production again, and updating to v2 there is currently infeasible due to the new DB format.

[jarifibrahim]

@guelfey ~Do you periodically run ValueLogGC? I noticed that in issue https://github.com/dgraph-io/badger/issues/1283, the block is because of value log GC https://github.com/dgraph-io/badger/issues/1283#issuecomment-611992830.~

Update - The issue in #1283 was specific to badger v2.x. The issue here is reported for badger v1.5.5 which does not have a cache.

[guelfey]

Seems to have been fixed by updating to badger 1.6 - will reopen if it occurs again

[jarifibrahim]

Thanks @guelfey!