Ah @mrjn here’s a better snapshot- apologies I forgot I had tracing still on for the last one. Your suspicion of CPU bottleneck on those hot predicates seems correct, furthermore it appears to be the root cause of cluster instability that results in my big memory blowups.
Hard to catch the spike which takes it to 27gb, but here I caught one at 9gb.
Once I kick up concurrency up, that particular alpha starts to get overwhelmed- logs like this- also seems like it had connection issues with its peers/zero:
W0509 01:20:03.764147 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 814ms. Breakdown: [{disk 814ms} {proposals 0s} {advance 0s}] Num entries: 0. MustSync: false
W0509 01:22:22.778423 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 412ms. Breakdown: [{disk 412ms} {proposals 0s} {advance 0s}] Num entries: 0. MustSync: false
W0509 01:23:02.882394 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 686ms. Breakdown: [{disk 623ms} {advance 62ms} {proposals 1ms}] Num entries: 0. MustSync: false
W0509 01:23:12.926267 1 node.go:420] Unable to send message to peer: 0x3. Error: Unhealthy connection
W0509 01:23:20.017682 1 node.go:420] Unable to send message to peer: 0x2. Error: Unhealthy connection
W0509 01:23:33.758306 1 pool.go:254] Connection lost with slafferty-dgraph-zero-1.slafferty-dgraph-zero-headless.slafferty.svc.cluster.local:5080. Error: rpc error: code = Unavailable desc = transport is closing
E0509 01:23:44.711037 1 groups.go:994] While proposing delta with MaxAssigned: 11979 and num txns: 0. Error=Server overloaded with pending proposals. Please retry later. Retrying...
I0509 01:23:57.994460 1 log.go:34] 1 [logterm: 15, index: 10299, vote: 1] rejected MsgPreVote from 3 [logterm: 15, index: 10272] at term 15
I0509 01:23:57.994660 1 log.go:34] 1 [logterm: 15, index: 10299, vote: 1] rejected MsgPreVote from 3 [logterm: 15, index: 10272] at term 15
E0509 01:24:29.603307 1 groups.go:994] While proposing delta with MaxAssigned: 11989 and num txns: 0. Error=Server overloaded with pending proposals. Please retry later. Retrying...
E0509 01:24:57.604428 1 groups.go:994] While proposing delta with MaxAssigned: 11989 and num txns: 0. Error=Server overloaded with pending proposals. Please retry later. Retrying...
I0509 01:25:28.257217 1 groups.go:929] Zero leadership changed. Renewing oracle delta stream.
E0509 01:25:28.257931 1 groups.go:905] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled
I0509 01:25:29.264755 1 groups.go:865] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0509 01:25:29.265130 1 groups.go:874] Got Zero leader: slafferty-dgraph-zero-2.slafferty-dgraph-zero-headless.slafferty.svc.cluster.local:5080
W0509 01:25:50.204076 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 1.357s. Breakdown: [{disk 1.357s} {proposals 0s} {advance 0s}] Num entries: 0. MustSync: false
W0509 01:25:52.878036 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 807ms. Breakdown: [{advance 807ms} {disk 0s} {proposals 0s}] Num entries: 0. MustSync: false
W0509 01:25:53.625515 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 641ms. Breakdown: [{advance 641ms} {disk 0s} {proposals 0s}] Num entries: 0. MustSync: false
W0509 01:25:54.827916 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 698ms. Breakdown: [{disk 698ms} {proposals 0s} {advance 0s}] Num entries: 0. MustSync: false
W0509 01:26:00.724864 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 1.141s. Breakdown: [{disk 1.141s} {proposals 0s} {advance 0s}] Num entries: 0. MustSync: false
Once this alpha goes down, the other alphas must try to take over with their replicas- however there’s a massive memory spike (25+ gb) when they do this, causing oom. This is a bit of a perpetual cycle and its hard for them to break out of it (especially if more mutations continually come in).
So yes, it seems like if mutations were able to run concurrently on the same predicate in ludicrous mode, that might mitigate my issue
BTW having so many jaeger traces throughout the core is fantastic
So- interesting thought. There’s no real reason all my entities need to have their xid live in the same predicate. For instance if I have TypeA…TypeZ in dgraph, I think I could just “namespace” the ids to the types. TypeA.id, TypeB.id, etc. This would balance the load of my “xid” predicate upserts across my dgraph types. Since I have a lot of types, this may be an effective solution for me- which Ill spend some time testing.
I still have the project predicate though- which is effectively my means of multi-tenancy. I suppose I could make it per-type as Im describing doing with xid, but that feels a little weird. I was also thinking about maybe making project a node that has a relationship to all-the-things… which I think would be cheaper since on disks that just a sorted list of ints that get compressed. Might work. I still have the risk of schema collisions across tenants… but thats another thing to tackle
I switched from having xid on all predicates and instead namespaced it by type… i.e VM_id, VCPU_id, etc (across about 200 types) and found some ludicrous performance.
1st mark is concurrency1: batch 200
2nd is concurrency 1 batch 1000
Third is concurrency 10 batch 1000
The last one was only using 10cpu, 12gb mem to push almost 80k! I was struggling to break 1000/s with 28 cores and 28gb mem with the xid-on-everything approach… so thats an 80x performance on half the hardware. Nice!
I was curious if I could push higher than this but any increase in concurrency or batchsize seems to hit diminishing returns even though Im below max cpu util.
Is there much of a downside of making my predicates as granular as possible? I suppose there would be some sort of a read performance penalty, but since my use case is less of searching for “name” across everything and more of searching for “name, type” tuple- perhaps its a better format for me.
Additionally, if I hit the nodes too hard and they oomkill, they’ll struggle to come back online due to big memory spikes (heap is quite small but total mem used by the process is high). Maybe I’ve exacerbated the replica-moving thrash by having so many predicates? I’ll try to grab some more data on that.
Given enough time or heavy inserting I’ll get back to the point where the cluster gets unhealthy and swallows lots of ram and boot loops from oomkills (even with all querying and inserting stopped).
I0511 22:07:47.213177 1 draft.go:822] Blocked pushing to applyCh for 50m11.988s
W0511 22:07:47.528009 1 draft.go:1183] Raft.Ready took too long to process: Timer Total: 50m16.661s. Breakdown: [{proposals 50m16.592s} {disk 70ms} {advance 0s}] Num entries: 3144. MustSync: true
The 4.7GB of memory usage is because of LoadToRam setting for opening Badger. Could be improved by instead setting it to mmap@seanlaff .
The 2.2GB of memory is because of zstd.Decompress. I think @ibrahim made a change to optimize that, IIRC.
Very nice!
Not really. That’s what we do for our GraphQL implementation. Each type’s fields is a different predicate internally (typename.fieldname).
That’d only happen if you have multiple shards. Also, Zero only does that calculation at a regular interval, so there would only be one move happening every so often. The time duration for that is configurable via a flag in Zero.
Thanks for the feedback. Good to hear about the predicates- and the mmap and zstd compression will be good tweaks to have in the back pocket.
Cluster has been idle for about 12 hours now and is still struggling to get out of its unhealthy state. Are there any other data/traces/logs that I could pull that would be helpful in diagnosing the slow badger replays/high cpu/mem?
@mrjn@seanlaff The badger db open doesn’t take too long to open
I0511 20:47:14.593184 17 log.go:34] All 258 tables opened in 1m11.905s
I0511 20:47:56.702918 17 log.go:34] All 864 tables opened in 38.226s
I0511 21:01:46.561048 1 log.go:34] All 258 tables opened in 54.605s
I0511 21:02:31.180809 1 log.go:34] All 911 tables opened in 40.731s
The maximum is 1 minute for 258 tables which is not super slow. It’s strange that 900+ tables were opened in 40s but it took 1m to open 258 tables.
I see that there was a point after which compactions got slow
I0511 21:16:50.409226 1 log.go:34] LOG Compact 2->3, del 5 tables, add 3 tables, took 1.356606356s
I0511 21:16:52.690498 1 log.go:34] LOG Compact 2->3, del 5 tables, add 4 tables, took 2.280474683s
I0511 21:16:53.854120 1 log.go:34] LOG Compact 2->3, del 5 tables, add 4 tables, took 3.594580144s
I0511 22:15:40.136795 1 log.go:34] LOG Compact 0->1, del 14 tables, add 10 tables, took 2m58.029109802s
I0511 22:33:12.274514 1 log.go:34] LOG Compact 1->2, del 9 tables, add 9 tables, took 17m32.13744674s
I0511 22:35:55.973987 1 log.go:34] LOG Compact 2->3, del 4 tables, add 3 tables, took 2m45.303871907s
I see only these 3 compactions that took some minutes. I have two possible explanations for the slow compactions
I think it might because the block cache doesn’t contain these blocks and they have to be decompressed always. We have a 1 GB block cache in alpha and this compaction alone would’ve tried to insert 540 MB (64*9) of data in the 17 minute long compaction which would lead to eviction of existing blocks from the cache.
The 9 tables from level 1 were decompressed and the new 9 tables on the level 2 were recompressed.
If performance is important, we should increase the cache size here, if memory is important we should keep the cache to default 1 GB.
Edit - The following point is invalid. The compactions don’t cascade from level 1 onwards. We do that only for level 0.
I see there were multiple compactions running at the same time https://gist.github.com/jarifibrahim/5fdd80275401ce950c07467e4bf780d2 . I believe it took 17 minutes because the lower levels might not have enough space to accommodate the new tables and the compaction cascaded to the lower levels.
So the cache plus cascading compactions could’ve caused the slow compactions.
Currently running v20.03.1. As my test went on, I added a few more (non-namespaced) predicates that had a moderate chance of being applied to any node. I also set the cardinality of the values for these predicates super low to see what would happen (I generate an int between 1-15, to simulate something like “orgID”, “deployEnv”, etc). Maybe the badger posting-lists for these just ballooned in size as would be expected? I noticed these large tablets in the new ratel ui for the low cardinality predicates I sent in.
200mb is pretty chunky so I could see that causing some churn in the 1gb cache you mentioned Perhaps I need to be aggressive as possible about namespacing all predicates to avoid that.
@seanlaff Those are pretty big tables. The default table size is 64 MB. We store all duplicate keys (with different versions) in a single table. This means you have a lot of duplicate keys. @mrjn is this expected? If the tables are of 200 mb size, the compactions and compression/decompression/cache would be affected.
How do we know that? Sean’s image shows Dgraph tablets, not Badger tables.
Also, what I saw from the logs was that the value log replay went on for a long while after the tables were opened. The question is, why did the value log need to be replayed from so far back? For around 14 mins, it was replaying the value log.
My bad. I confused badger tables with dgraph tablets.
This is because we keep level 0 in memory. So in case of a crash, the data in level 0 and memtable has to be replayed. This means more data has to be ingested during replay leading to more compactions which leads to longer replays.
Heya so I ran another test with namespacing all the predicates by type- everything ran pretty smooth and level, however since go is greedy about not returning memory, it slowly climbs and it’ll eventually oomkill.
The good news is I don’t see outrageous memory spikes on reboot using this namespacing-everything pattern, however it looks like the rebooting alpha is taking a really long time to catch back up. My mutations are hanging (which is the back pressure I’d assume to see), but I’m 25m in and it’s still exhibiting this behavior.
Do the replays happening serially? Maybe since I have 1000 predicates that slows down the replay? Any advice on how to speed this up? If I run more than 3 dgraph alphas maybe it’ll be easier for the cluster to hot-swap over to a new alpha while the rebooting one finally catches up- although Im not sure if that rebooting one would trigger cluster-wide unhleathiness.
@seanlaff Can you try this build with @Paras’s change in PR #5442? It sets KeepL0InMemory to false. The Docker image is called dgraph/dgraph:v20.03.1-l0notinmemory.
