Slow Queries After Doing A Bulk Load On Nightly Build

[willcj33]

Version:

Dgraph version   : v0.7.7-dev
Commit SHA-1     : 07abc9a2
Commit timestamp : 2017-07-10 19:24:11 +1000
Branch           : HEAD

I am experiencing LONG delays (3.5-10s) on queries (usually heavily filtered ones that access a lot of related data) within hours of restoring data to the newest release of Dgraph. My CPU seems lost (< 10%) pretty much at all times. I try to restart it, and it does nothing to help. When I run it a second time (same query), What took 5s, takes 35ms (which is how fast it ran on 0.7.7). Seemingly, after a day or so of this instance running (untouched) the speeds are faster that 0.7.7, where after a restart (to ensure no caching or anything), what took 35ms on 0.7.7, takes around 8ms on master, but it seems I have to wait some random amount of time. UID queries are blazing fast always. Tagging @janardhan1993 and @pawanrawal as they are most familiar with my issue.

[willcj33]

profile (19).zip

Added a profile for when these long queries happen. This one actually times out through the UI. This is hours after my data load when making this ticket.

[willcj33]

It finally returned in 37 seconds. This is a millisecond response on 0.7.7, so something is going on here for sure. This is after I bulk loaded data still, 2 hours after. I have also restarted the server once to try to fix the speed issues. Attached my /debug/vars at the time this is happening.

vars.pdf

[pawanrawal]

(pprof) top10       
1680ms of 2660ms total (63.16%)
Dropped 38 nodes (cum <= 13.30ms)
Showing top 10 nodes out of 109 (cum >= 80ms)
      flat  flat%   sum%        cum   cum%
     240ms  9.02%  9.02%      260ms  9.77%  github.com/AndreasBriese/bbloom.Bloom.Has
     230ms  8.65% 17.67%      230ms  8.65%  runtime.usleep
     200ms  7.52% 25.19%      200ms  7.52%  runtime.cmpbody
     180ms  6.77% 31.95%      390ms 14.66%  github.com/dgraph-io/badger/table.(*BlockIterator).parseKV
     170ms  6.39% 38.35%      560ms 21.05%  github.com/dgraph-io/badger/table.(*BlockIterator).Next
     160ms  6.02% 44.36%      160ms  6.02%  runtime.memmove
     150ms  5.64% 50.00%      350ms 13.16%  runtime.mallocgc
     140ms  5.26% 55.26%      160ms  6.02%  syscall.Syscall6
     130ms  4.89% 60.15%      130ms  4.89%  runtime.futex
      80ms  3.01% 63.16%       80ms  3.01%  runtime.memclrNoHeapPointers

(pprof) top10 --cum
0.05s of 2.66s total ( 1.88%)
Dropped 38 nodes (cum <= 0.01s)
Showing top 10 nodes out of 109 (cum >= 0.88s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%      2.35s 88.35%  runtime.goexit
     0.01s  0.38%  0.38%      1.77s 66.54%  github.com/dgraph-io/badger.(*KV).get
     0.01s  0.38%  0.75%      1.67s 62.78%  github.com/dgraph-io/badger.(*logFile).iterate
         0     0%  0.75%      1.67s 62.78%  github.com/dgraph-io/badger.(*valueLog).doRunGC
         0     0%  0.75%      1.67s 62.78%  github.com/dgraph-io/badger.(*valueLog).runGCInLoop
         0     0%  0.75%      1.60s 60.15%  github.com/dgraph-io/badger.(*valueLog).doRunGC.func1
     0.03s  1.13%  1.88%      1.56s 58.65%  github.com/dgraph-io/badger.(*levelHandler).get
         0     0%  1.88%      1.56s 58.65%  github.com/dgraph-io/badger.(*levelsController).get
         0     0%  1.88%      0.88s 33.08%  github.com/dgraph-io/badger/table.(*TableIterator).Seek
         0     0%  1.88%      0.88s 33.08%  github.com/dgraph-io/badger/table.(*TableIterator).seek

[manishrjain]

We can make our GC smarter. Right now, it just starts testing if a value log needs to be rewritten every 10 mins. We need to expose some vars from Badger to be able to really figure out what to optimize there. Maybe we can allow a user to turn it off entirely. Or, reduce how many iterations it does before deciding to rewrite the file.

[manishrjain]

So, @willcj33 : This randomness of being slow, sounds to me like it is a GC problem. And the cpu profiling indicates that well. We could just reduce the amount of GC work going on in the background, and that should be sufficient here.

Is this blocking for you? Do you see this often?

Also, @janardhan1993 : Didn't you change the table mapping to memory? I think that would affect this heavily. We should just set it back to load to RAM (and provide a flag to allow users to change it to memory map or nothing, with a warning that things would be slow).

[manishrjain]

So, to summarize, I think the real change that's required here is to have LSM tree be in RAM. That would speed up both the GC effort in background and the startup slowness mentioned in #1180 .

Having said that, we can also reduce the megabytes of data we comb through in value log for GC (reduce from 100 to 50 MB, @pawanrawal ).

[pawanrawal]

@willcj33 confirmed that after switching to using SSD this is not an issue anymore.

@manishrjain should we still reduce the window size?

[manishrjain]

No need. I think the main diff is load to ram. Sent from Nexus 6P

…

On Jul 16, 2017 5:18 PM, "Pawan Rawal" ***@***.***> wrote: @willcj33 <https://github.com/willcj33> confirmed that after switching to using SSD this is not an issue anymore. @manishrjain <https://github.com/manishrjain> should we still reduce the window size? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1168 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABsyNCzxXGfUZgXsnkJuNrZd0p_COMrpks5sOqhWgaJpZM4OS6c9> .