GC discardStat fallback mechanism

[requilence]

This PR aims to fix the GC issue described here
https://discuss.dgraph.io/t/gc-may-not-work-in-some-cases/17197

The idea is to calculate discardStat directly on vlog in case discard data is not available. Because current discardStat calculation only done on compaction it may be not available until memtables got full. Check the issue on forum for the reproduction steps.

Also during the tests I've found out that value log rewrite doesn't work well when the key was removed so I've tried to fix this at the line 238-240

[CLAassistant]

All committers have signed the CLA.

[manishrjain]

It's an expensive operation to calculate the GC for the value log in this manner. We used to do this before, but it burnt a lot of CPU cycles. And given the scenario the OP has (small number of keys), they'd be better off just increasing the value threshold, to avoid value log usage as much as possible.

This shouldn't have been merged.

[requilence]

@manishrjain Yes, I understand this is not a cheap operation. But what is the reason to

• save CPU cycles for GC(which is btw triggered only manually) and make it inoperable as a result
• have the Value Log as one of the main advantages of Badger and disabling it with ValueThreshold?

[requilence]

Also, this fallback mechanism takes place only in case it was no calculated discardState available. This means no compactions have been done, which means not a lot of keys have been written

[lithp]

I'm experiencing deadlocks which I believe this commit introduced. I've cherry-picked this commit onto v3.2103.2:

1. pickLog, called by the garbage collector, takes out a lock on vlog.filesLock
2. it then calls calculateDiscardStat(introduced by this PR) which calls vlog.db.orc.readTs(), which calls o.txnMark.WaitForMark
   • The GC is now blocked, waiting for all committed transactions to finish
3. The GC will be unblocked when the transaction calls doneCommit, updating the watermark, but first the writes actually need to happen, so the transaction waits for doWrites() to complete.
   • The GC is now blocked on the transaction which is blocked on doWrites().
4. The transaction will be unblocked when doWrites calls done. But first, doWrites must add the new values to the vlog!
5. If current vlog file is too big then a new vlog file will need to be created. However, doing so requires taking out a lock on vlog.filesLock, the same thing we locked in step (1) and now the deadlock is complete!
6. In summary: our GC is blocked on the watermark update, but the transaction can't update the watermark until doWrites() finishes writing, but doWrites() can't finish writing until it creates the new vlog file, and it can't do that until the GC releases its lock.

I don't know enough about badger to know how to fix this. I believe the call to readTs() ought to be a call to discardAtOrBelow(), which is what the normal GC codepath uses. Making that change fixes my deadlock problem, but this is my first day in the badger codebase and I'm reticent to play with locks I don't understand.

[pandeyshubham25]

@lithp Thankyou for bringing this up. We are taking a look into this. Meanwhile, we wanted to understand a few things from you -

1. Can you describe the usecase which is leading you to this situation?
2. Other than the change you mentioned in the end, have you tried reverting this commit's change altogether and see if that works?

[joshua-goldstein]

@lithp Thank you for the detailed analysis. Do you have a stack trace available to share, when the deadlock occurs?

[pandeyshubham25]

@lithp , Thanks again for sharing your observations that helped us do the preliminary analysis. After further verifying the change you recommended, we plan on remediating this issue as soon as we can.

[lithp]

Thank you for looking at this! I just checked my notes and unfortunately I did not save the original stacktraces. I can't tell from your last comment, @joshua-goldstein, would you still like a stack trace? I can try to reproduce the deadlock.

[lithp]

I reproduced the deadlock and have some stack traces for you.

This is the goroutine which runs in the background and takes out a lock on vlog.filesLock before blocking on the watermark update:

 0  0x000000000043ce5c in runtime.gopark
    at /usr/local/go/src/runtime/proc.go:362
 1  0x000000000044c9f4 in runtime.selectgo
    at /usr/local/go/src/runtime/select.go:328
 2  0x0000000000a5c5d4 in github.com/dgraph-io/badger/v3/y.(*WaterMark).WaitForMark
    at /home/parallels/wc/badger/y/watermark.go:122
 3  0x0000000000bc0bec in github.com/dgraph-io/badger/v3.(*oracle).readTs
    at /home/parallels/wc/badger/txn.go:103
 4  0x0000000000bc7984 in github.com/dgraph-io/badger/v3.(*valueLog).calculateDiscardStat.func1
    at /home/parallels/wc/badger/value.go:190
 5  0x0000000000bc7828 in github.com/dgraph-io/badger/v3.(*valueLog).calculateDiscardStat.func2
    at /home/parallels/wc/badger/value.go:204
 6  0x0000000000bb1af8 in github.com/dgraph-io/badger/v3.(*logFile).iterate
    at /home/parallels/wc/badger/memtable.go:539
 7  0x0000000000bc76e4 in github.com/dgraph-io/badger/v3.(*valueLog).calculateDiscardStat
    at /home/parallels/wc/badger/value.go:203
 8  0x0000000000bcead8 in github.com/dgraph-io/badger/v3.(*valueLog).pickLog
    at /home/parallels/wc/badger/value.go:1056
 9  0x0000000000bcf278 in github.com/dgraph-io/badger/v3.(*valueLog).runGC
    at /home/parallels/wc/badger/value.go:1153
10  0x0000000000b85130 in github.com/dgraph-io/badger/v3.(*DB).RunValueLogGC
    at /home/parallels/wc/badger/db.go:1216
11  0x0000000000c43674 in github.com/Worldcoin/hubble-commander/db.(*Database).TriggerGC
    at ./db/db.go:64
12  0x0000000000dc49b0 in github.com/Worldcoin/hubble-commander/storage.(*Storage).TriggerGC
    at ./storage/storage.go:133
13  0x0000000000fbbc8c in github.com/Worldcoin/hubble-commander/commander.(*Commander).newBlockLoop.func1
    at ./commander/new_block.go:49
14  0x000000000046b064 in runtime.goexit
    at /usr/local/go/src/runtime/asm_arm64.s:1259

This is the goroutine which attempts to perform a transaction and waits for the background thread to perform the writes:

 0  0x000000000043ce5c in runtime.gopark
    at /usr/local/go/src/runtime/proc.go:362
 1  0x000000000043cee8 in runtime.goparkunlock
    at /usr/local/go/src/runtime/proc.go:367
 2  0x000000000044d4ec in runtime.semacquire1
    at /usr/local/go/src/runtime/sema.go:144
 3  0x0000000000466eec in sync.runtime_Semacquire
    at /usr/local/go/src/runtime/sema.go:56
 4  0x000000000047ad00 in sync.(*WaitGroup).Wait
    at /usr/local/go/src/sync/waitgroup.go:136
 5  0x0000000000bcbff8 in github.com/dgraph-io/badger/v3.(*request).Wait
    at /home/parallels/wc/badger/value.go:744
 6  0x0000000000bc4270 in github.com/dgraph-io/badger/v3.(*Txn).commitAndSend.func3
    at /home/parallels/wc/badger/txn.go:609
 7  0x0000000000bc4888 in github.com/dgraph-io/badger/v3.(*Txn).Commit
    at /home/parallels/wc/badger/txn.go:679
 8  0x0000000000bc5798 in github.com/dgraph-io/badger/v3.(*DB).Update
    at /home/parallels/wc/badger/txn.go:826
 9  0x0000000000c03dcc in github.com/timshannon/badgerhold/v4.(*Store).Upsert
    at /home/parallels/go/pkg/mod/github.com/timshannon/badgerhold/v4@v4.0.3-0.20220211134925-a440b802de24/put.go:175
10  0x0000000000c443b0 in github.com/Worldcoin/hubble-commander/db.(*Database).Upsert
    at ./db/db.go:171
11  0x0000000000dbbc3c in github.com/Worldcoin/hubble-commander/storage.(*ChainStateStorage).SetChainState
    at ./storage/chain_state.go:47
12  0x0000000000dbb5f8 in github.com/Worldcoin/hubble-commander/storage.(*ChainStateStorage).SetSyncedBlock
    at ./storage/block_number.go:22
13  0x0000000000fbc8e0 in github.com/Worldcoin/hubble-commander/commander.(*Commander).syncForward
    at ./commander/new_block.go:197
14  0x0000000000fbc4c4 in github.com/Worldcoin/hubble-commander/commander.(*Commander).syncToLatestBlock
    at ./commander/new_block.go:153
15  0x0000000000fbc0fc in github.com/Worldcoin/hubble-commander/commander.(*Commander).syncAndManageRollbacks
    at ./commander/new_block.go:112
16  0x0000000000fbbea0 in github.com/Worldcoin/hubble-commander/commander.(*Commander).newBlockLoopIteration
    at ./commander/new_block.go:81
17  0x0000000000fbb9a8 in github.com/Worldcoin/hubble-commander/commander.(*Commander).newBlockLoop
    at ./commander/new_block.go:69
18  0x0000000000fb4cd0 in github.com/Worldcoin/hubble-commander/commander.(*Commander).Start.func5
    at ./commander/commander.go:141
19  0x0000000000fc0fb0 in github.com/Worldcoin/hubble-commander/commander.(*workers).startWorker.func1
    at ./commander/workers.go:44
20  0x000000000046b064 in runtime.goexit
    at /usr/local/go/src/runtime/asm_arm64.s:1259

This is the doWrites goroutine which blocks on vlog.filesLock, completing the deadlock:

0  0x000000000043ce5c in runtime.gopark
    at /usr/local/go/src/runtime/proc.go:362
 1  0x000000000043cee8 in runtime.goparkunlock
    at /usr/local/go/src/runtime/proc.go:367
 2  0x000000000044d4ec in runtime.semacquire1
    at /usr/local/go/src/runtime/sema.go:144
 3  0x0000000000466fd8 in sync.runtime_SemacquireMutex
    at /usr/local/go/src/runtime/sema.go:71
 4  0x000000000047a5e8 in sync.(*RWMutex).Lock
    at /usr/local/go/src/sync/rwmutex.go:144
 5  0x0000000000bca84c in github.com/dgraph-io/badger/v3.(*valueLog).createVlogFile
    at /home/parallels/wc/badger/value.go:566
 6  0x0000000000bccf68 in github.com/dgraph-io/badger/v3.(*valueLog).write.func3
    at /home/parallels/wc/badger/value.go:881
 7  0x0000000000bccde0 in github.com/dgraph-io/badger/v3.(*valueLog).write
    at /home/parallels/wc/badger/value.go:940
 8  0x0000000000b82128 in github.com/dgraph-io/badger/v3.(*DB).writeRequests
    at /home/parallels/wc/badger/db.go:816
 9  0x0000000000b8306c in github.com/dgraph-io/badger/v3.(*DB).doWrites.func1
    at /home/parallels/wc/badger/db.go:887
10  0x0000000000b82fe0 in github.com/dgraph-io/badger/v3.(*DB).doWrites.func3
    at /home/parallels/wc/badger/db.go:940
11  0x000000000046b064 in runtime.goexit
    at /usr/local/go/src/runtime/asm_arm64.s:1259