DGraph Times Out Processing Graph

[jm4games]

Dgraph Version?

Dgraph version : v1.1.0
Dgraph SHA-256 : 7d4294a80f74692695467e2cf17f74648c18087ed7057d798f40e1d3a31d2095
Commit SHA-1 : ef7cdb2

Hardware Spec ?

OS: Arch Linux, (running dgraph in docker env)
CPU: AMD 3900x
RAM: 64GB

Steps to reproduce the issue (command/config used to run Dgraph).

schema.txt - graph layout
trait.txt - initial seed data
graph.gz - (full graph)

Commands:
Update schema through dgraph web UI (copy and paste schema.txt into schema bulk edit)
Then run the following from shell in dir where downloaded trait.txt.gz and graph.gz exist.

$ curl -X POST -H 'Content-Encoding: gzip' -H "Content-Type: application/rdf" localhost:8080/mutate\?commitNow=true --data-binary @trait.txt.gz
$ curl -X POST -H 'Content-Encoding: gzip' -H "Content-Type: application/rdf" localhost:8080/mutate\?commitNow=true --data-binary @graph.gz

Expected behaviour and actual result.

Dgraph should process the graph, but instead spins on it and never completes processing.

Other

I know the graph itself is sound as I have processed smaller data sets with the exact layout. It seems once a graph reaches a certain size dgraph can no longer process it. Maybe I have exceed some sort of internal limit. I have also attached log of dgraph server and it looks like a raft consensus is timing out.

Files

graph.gz
error.log
schema.txt
trait.txt.gz

[MichelDiz]

What exactly are you doing? Is it a bulk load? live load?

The file graph.gz isn't correct for bulk. Bulk or Live only accepts Nquads or JSON. No upsert or even the format:

mutation {
set {

    }
}

If you wanna change something, you should do it after the load via upsert. Not during the load.

What is the config of your cluster (how many groups, instances) do you have?

[jm4games]

This is on a single box using 1 dgraph/zero/ratel server (e.g. the getting started docker-compose). This uses the standard localhost:8080/mutate endpoint (with commitNow=true). The graph.gz is a dump of what I am posting to the endpoint.

[MichelDiz]

How much RAM does it consume? doing this.

[jm4games]

It would do occasional spikes and then eventually sit at 6~10GB. I would have to run it again to make sure and I won't be at my dev box for a while. But the graphj.gz is only ~168 mb unzipped, so I am kind of surprised it was taking so much ram.

[jm4games]

@MichelDiz I updated description with proper repo steps (sorry should have done that to begin with). Got onto a laptop and performed repo, I killed dgraph once it started to exceed 10GB in RAM.

Also fixed traits.txt (now traits.txt.gz)

[MichelDiz]

As you have a lot of RAM available, try to run your cluster with these flags (Just for this situation):

--badger.tables=ram
--badger.vlog=mmap

dgraph alpha -h

 --badger.tables string  [ram, mmap, disk] 
Specifies how Badger LSM tree is stored. Option sequence consume most to least RAM while providing best to worst read performance respectively. (default "mmap")
 --badger.vlog string  [mmap, disk] 
Specifies how Badger Value log is stored. mmap consumes more RAM, but provides better performance. (default "mmap")

[jm4games]

Ok I will have to give it a shot tonight, my current laptop doesn't have near as much ram :)

[MichelDiz]

What I have indicated is a way of assessing whether it could be bottleneck by I/O.

I would then recommend that you have an actual cluster, where each group has its own resources. A single instance with slow HDD tends to have poor performance. But if you have multiple instances with own resources, even with slow HDDs and well-defined groups, there is no performance loss.

Also, Dgraph/BadgerDB works better with SSD/NVMe.

[jm4games]

So I am running on a corsair MP600, that gets about 4250MB/s in write throughput, so I doubt its IO bound. You wont even see those speeds in a small cluster setup. The only thing that i can think that might prevent this is I am using a docker volume and that could be IO limited.

[jm4games]

So it seems these flags did not make any difference. I've also noticed that since the request failed to fully process, dgraph tries to recover it when I restart the server. The recovered "job?" causes the server to start spinning again. The server also doesn't seem to be responsive to simple query commands.

[jm4games]

Also, I've been monitoring the server trying to process the job for over 15 min and the server is sitting at 7.5GBof ram use (which has stayed consistent when reached, slowly rising though) and fluctuates from using 2 vcores to all 24 vcores. I don't see much io activity (via iotop). I suspect maybe golangs GC is kicking in for a massive cleanup when i hit all 24 cores?

[MichelDiz]

Quick question, how do you run it? 185MB via Ratel?

[jm4games]

how to I run the request? I run all servers via docker-compose and send the request via localhost:8080/mutate which is alpha

[jm4games]

Looks like job finally finished (but didn't commit graph changes)

server_1  | W1101 14:16:42.413590       1 draft.go:916] Inflight proposal size: 189262822. There would be some throttling.
server_1  | W1101 14:16:42.413866       1 draft.go:958] Raft.Ready took too long to process: Timer Total: 1.064s. Breakdown: [{proposals 1.064s} {disk 0s} {advance 0s}] Num entries: 0. MustSync: false
server_1  | I1101 14:58:11.000551       1 draft.go:637] Blocked pushing to applyCh for 41m28.587s
server_1  | W1101 14:58:11.000616       1 draft.go:958] Raft.Ready took too long to process: Timer Total: 41m28.587s. Breakdown: [{proposals 41m28.587s} {disk 0s} {advance 0s}] Num entries: 0. MustSync: false
server_1  | I1101 14:58:13.865419       1 log.go:34] 1 is starting a new election at term 5
server_1  | I1101 14:58:13.865450       1 log.go:34] 1 became pre-candidate at term 5
server_1  | I1101 14:58:13.865457       1 log.go:34] 1 received MsgPreVoteResp from 1 at term 5
server_1  | I1101 14:58:13.865498       1 log.go:34] 1 became candidate at term 6
server_1  | I1101 14:58:13.865504       1 log.go:34] 1 received MsgVoteResp from 1 at term 6
server_1  | I1101 14:58:13.865546       1 log.go:34] 1 became leader at term 6
server_1  | I1101 14:58:13.865554       1 log.go:34] raft.node: 1 elected leader 1 at term 6
server_1  | I1101 14:58:14.765325       1 groups.go:808] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
server_1  | I1101 14:58:14.765349       1 groups.go:817] Got Zero leader: zero:5080
q

[MichelDiz]

ah, just saw your update in the first comment

curl -X POST -H 'Content-Encoding: gzip' -H "Content-Type: application/rdf" localhost:8080/mutate\?commitNow=true --data-binary @graph.gz