v2 much slower then v1.6.0

[adwinsky]

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

$ go version
1.13.8

What version of Badger are you using?

v2.0.2
opts := badger.DefaultOptions(fmt.Sprintf(dir + "/" + name))
opts.SyncWrites = false
opts.ValueLogLoadingMode = options.FileIO

Does this issue reproduce with the latest master?

Yes

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

Samsung nvme disk SAMSUNG MZPLL3T2HMLS-00003
Linux: 18.04.2 LTS (Bionic Beaver)

What did you do?

As I mentioned in other ticket #1228 I am unable to use Badger v2 version because it's very slow.

What did you expect to see?

I expect Badger v2 version to be similarly fast as v1.6.0

What did you see instead?

One great example is when I run RunValueLogGC function it can take up to 20 minutes. I have rather database (about 10 GB), and with v1.6.0 same operation takes up to 30s.

Have a look at debug/request output:

When | Elapsed (s)
-- | --
2020/03/11 13:37:28.017837 | 464.393672 | GC
13:37:28.017850 | .    13 | ... Could not find candidate via discard stats. Randomly picking one.
13:37:28.017857 | .     8 | ... Randomly chose fid: 1
13:37:28.017865 | .     7 | ... Size window: 125606803.00. Count window: 10000.
13:37:28.017866 | .     2 | ... Skip first 324.58 MB of file of size: 1197 MB
13:37:28.906299 | .888433 | ... Stopping sampling after 10000 entries.
13:37:28.906306 | .     7 | ... Fid: 1. Skipped: 324.58MB Num iterations: 260627. Data  status={total:20.11733341217041 discard:19.84939193725586 count:10001}
13:37:28.906333 | .    28 | ... Rewriting fid: 1
13:43:47.537655 | 378.631322 | ... Processing entry 100000

Processing 100000 entries takes more than 6 minutes! I noticed most of the time is spend here:

https://github.com/dgraph-io/badger/blob/master/value.go#L517

Very often it takes 20-50ms for single lookup. I think this also explains why overall performance of my application is significantly slower when I switch from 1.6.0 to 2

Here is the output of pprof profiling

Showing top 10 nodes out of 49
      flat  flat%   sum%        cum   cum%
    6870ms 22.74% 22.74%     6870ms 22.74%  encoding/json.stateInString
    5760ms 19.07% 41.81%    12630ms 41.81%  encoding/json.checkValid
    4170ms 13.80% 55.61%     4620ms 15.29%  github.com/dgraph-io/ristretto/z.newWithBoolset
    3930ms 13.01% 68.62%     3930ms 13.01%  encoding/json.unquoteBytes
    2170ms  7.18% 75.80%     2170ms  7.18%  encoding/json.(*decodeState).rescanLiteral
    1850ms  6.12% 81.93%     3570ms 11.82%  encoding/base64.(*Encoding).Decode
    1540ms  5.10% 87.02%     1540ms  5.10%  encoding/base64.assemble64
    1220ms  4.04% 91.06%     1220ms  4.04%  runtime.memclrNoHeapPointers
     730ms  2.42% 93.48%      730ms  2.42%  runtime.memmove
     320ms  1.06% 94.54%     2030ms  6.72%  runtime.mallocgc

[jarifibrahim]

Duplicate of #1254 . Thanks @adwinsky. I'll look at this issue.

[jarifibrahim]

Hey @adwinsky, I've raised #1256 to fix this.
Major performance improvement comes from #1256 and #1257 also improves the performance.

[adwinsky]

Many thanks for quick reaction @jarifibrahim. The performance is much better with your fix

[jarifibrahim]

@adwinsky I've merged PRs #1257 and #1260 which have fixed to a performance issue in latest badger. We'll soon release v2.0.3 with these fixes.

Thanks for profiling the code. It's much easier to fix issues when there's a profile attached to it. :)