Help needed: dgraph keeps crashing under load - what s going on?

Users Dgraph
1

How to handle this errors?
rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection closed

When i load some data (addresses ca. 35mb in csv but the files from dgraph are ca 20x bigger) into dgraph, i experience many dropouts.

i run dgraph latest on win10
configuration like in the tour:
Run dgraphzero
docker run -it -p 5080:5080 -p 6080:6080 -p 8080:8080 -p 9080:9080 -p 8000:8000 -v ~/dgraph:/dgraph --name dgraph dgraph/dgraph dgraph zero
In another terminal, now run dgraph
docker exec -it dgraph dgraph alpha --lru_mb 2048 --zero localhost:5080
And in another, run ratel (Dgraph UI)
docker exec -it dgraph dgraph-ratel

First error
go driver displayed error is:
rpc error: code = Unknown desc = Assigning IDs is only allowed on leader.

here are more logs:

I0406 11:14:25.475611 19 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
I0406 11:14:25.475749 19 log.go:34] Running for level: 0
I0406 11:14:33.392765 19 log.go:34] LOG Compact 0->1, del 6 tables, add 4 tables, took 7.915310339s
I0406 11:14:33.392863 19 log.go:34] Compaction for level: 0 DONE
I0406 11:15:06.652107 19 draft.go:374] Creating snapshot at index: 10066. ReadTs: 9141.
I0406 11:18:05.030276 19 log.go:34] Rolling up Created batch of size: 55 B in 64.567µs.
I0406 11:18:07.536310 19 log.go:34] Rolling up Created batch of size: 4.3 MB in 2.11884214s.
I0406 11:18:07.536583 19 log.go:34] Rolling up Time elapsed: 02s, bytes sent: 4.3 MB, speed: 2.1 MB/sec
I0406 11:18:09.650416 19 log.go:34] Rolling up Created batch of size: 4.3 MB in 2.110223791s.
I0406 11:18:09.650456 19 log.go:34] Rolling up Time elapsed: 04s, bytes sent: 8.6 MB, speed: 2.1 MB/sec
I0406 11:18:15.051080 19 log.go:34] Rolling up Created batch of size: 8.6 MB in 5.380655874s.
I0406 11:18:15.051976 19 log.go:34] Rolling up Time elapsed: 10s, bytes sent: 17 MB, speed: 1.7 MB/sec
I0406 11:18:22.223741 19 log.go:34] Rolling up Created batch of size: 13 MB in 7.133612826s.
I0406 11:18:22.227408 19 log.go:34] Rolling up Time elapsed: 17s, bytes sent: 30 MB, speed: 1.8 MB/sec
I0406 11:18:50.761656 19 log.go:34] Rolling up Created batch of size: 51 MB in 28.382583549s.
I0406 11:18:50.765268 19 log.go:34] Rolling up Time elapsed: 45s, bytes sent: 81 MB, speed: 1.8 MB/sec
I0406 11:19:13.585314 19 log.go:34] Rolling up Created batch of size: 125 MB in 22.374038505s.
I0406 11:19:14.752045 19 log.go:34] Rolling up Created batch of size: 8.6 MB in 1.156978495s.
I0406 11:19:14.752608 19 log.go:34] Rolling up Sent 1910271 keys
I0406 11:19:14.786677 19 draft.go:1040] Rolled up 1910271 keys. Done
I0406 11:19:14.786780 19 draft.go:415] List rollup at Ts 9141: OK.
I0406 11:19:14.840250 19 predicate_move.go:191] Was instructed to delete tablet: Event
I0406 11:19:14.844316 19 index.go:1000] Dropping predicate: [Event]
I0406 11:19:14.848553 19 log.go:34] Writes flushed. Stopping compactions now…
I0406 11:19:14.967363 19 log.go:34] Got compaction priority: {level:0 score:1.74 dropPrefix:[0 0 5 69 118 101 110 116]}
I0406 11:19:14.967427 19 log.go:34] Running for level: 0
I0406 11:19:22.653368 19 log.go:34] LOG Compact 0->1, del 9 tables, add 3 tables, took 7.683243624s
I0406 11:19:22.657374 19 log.go:34] Compaction for level: 0 DONE
I0406 11:19:24.549859 19 log.go:34] LOG Compact 1->1, del 1 tables, add 1 tables, took 1.889192783s
I0406 11:19:24.550479 19 log.go:34] DropPrefix done
I0406 11:19:24.550860 19 log.go:34] Resuming writes
I0406 11:19:24.553204 19 schema.go:79] Deleting schema for predicate: [Event]
I0406 11:19:24.569747 19 predicate_move.go:191] Was instructed to delete tablet: User
I0406 11:19:24.577928 19 index.go:1000] Dropping predicate: [User]
I0406 11:19:24.577986 19 log.go:34] Writes flushed. Stopping compactions now…
I0406 11:19:24.686624 19 log.go:34] Got compaction priority: {level:0 score:1.74 dropPrefix:[0 0 4 85 115 101 114]}
I0406 11:19:24.687525 19 log.go:34] Running for level: 0
W0406 11:19:24.820105 19 draft.go:1071] While sending membership to Zero. Error: rpc error: code = DeadlineExceeded desc = context deadline exceeded
I0406 11:19:26.202541 19 log.go:34] LOG Compact 0->1, del 2 tables, add 1 tables, took 1.509975941s
I0406 11:19:26.204846 19 log.go:34] Compaction for level: 0 DONE
I0406 11:19:26.205370 19 log.go:34] DropPrefix done
I0406 11:19:26.206016 19 log.go:34] Resuming writes
I0406 11:19:26.208229 19 schema.go:79] Deleting schema for predicate: [User]
I0406 11:20:05.042530 19 draft.go:1291] Skipping snapshot at index: 10105. Insufficient discard entries: 1. MinPendingStartTs: 9176
I0406 11:21:05.049522 19 draft.go:1291] Skipping snapshot at index: 10105. Insufficient discard entries: 1. MinPendingStartTs: 9176
I0406 11:21:05.053832 19 draft.go:1132] Found 1 old transactions. Acting to abort them.
I0406 11:21:05.130042 19 draft.go:1093] TryAbort 1 txns with start ts. Error:
I0406 11:21:05.131167 19 draft.go:1116] TryAbort selectively proposing only aborted txns: txns:<start_ts:9176 >
I0406 11:21:05.137876 19 draft.go:1135] Done abortOldTransactions for 1 txns. Error:

Then i get the following errors:
rpc error: code = Unavailable desc = transport is closing

then alpha is down - after starting it up again i get the following error:
code = Unknown desc = Pending transactions found. Please retry operation

i need to shut down alpha manually and restart it, and then the pending transaction err is gone.

here are the logs from alpha:

W0406 12:26:19.746915 280 draft.go:958] Raft.Ready took too long to process: Timer Total: 626ms. Breakdown: [{disk 615ms} {proposals 6ms} {sync 0s} {advance 0s}] Num entries: 1. MustSync: true
W0406 12:26:21.189954 280 draft.go:958] Raft.Ready took too long to process: Timer Total: 885ms. Breakdown: [{disk 837ms} {proposals 41ms} {sync 0s} {advance 0s}] Num entries: 1. MustSync: true
W0406 12:26:33.860275 280 draft.go:958] Raft.Ready took too long to process: Timer Total: 2.417s. Breakdown: [{disk 1.822s} {proposals 337ms} {advance 16ms} {sync 13ms}] Num entries: 1. MustSync: true
W0406 12:26:43.396369 280 draft.go:958] Raft.Ready took too long to process: Timer Total: 2.004s. Breakdown: [{disk 1.829s} {proposals 13ms} {sync 0s} {advance 0s}] Num entries: 1. MustSync: true
W0406 12:26:45.206754 280 draft.go:958] Raft.Ready took too long to process: Timer Total: 1.077s. Breakdown: [{disk 1.004s} {proposals 32ms} {advance 18ms} {sync 0s}] Num entries: 1. MustSync: true
I0406 12:26:54.120364 280 groups.go:872] Zero leadership changed. Renewing oracle delta stream.
I0406 12:27:02.794360 280 groups.go:808] Leader idx=0x1 of group=1 is connecting to Zero for txn updates
I0406 12:27:02.803518 280 groups.go:817] Got Zero leader: localhost:5080
E0406 12:27:02.795405 280 groups.go:848] Error in oracle delta stream. Error: rpc error: code = Canceled desc = context canceled

2

Finally after crashing dgraph about 100 times, i came up with a rather ugly solution.

Mostly the errors came from compaction and the raft took too long thingy.
Sometimes Dgraph was in a very annoying state after crash, where it was in an endless loop of trying to playback the files. i had to rm -rf all the time.
To load the ~16000 json files with just a few hundred mutations in each file, i wrote a file walker and simply called dgo mutate for each file. The first approach crashed like the live loader.

On a bigger machine (with latest generation nvme drive) i gave docker 16 CPUs and 32 gb of ram - it almost did the whole folder in one go, but crashed again near the finish line.
But with more ram and more cpus it went definitely 4-5 times longer than with less resources.

adding a time.Sleep(time.Duration(10) * time.Second) every 100 files, so that the raft and compaction can do its thing and catch up in the sleeptime did the trick for me - but the whole import now takes over 16 Minutes…most of the time the machine is idleling around.

A thing worth to mention is, that the processing time gets worse and worse on every compaction/raft, although the machine is pretty much in idle state.
Below are the logs from the complete run, where you can see this behaviour and a failed raft - could not be from the disk/ram/cpu etc. - why is this happening?

We are a bit concerned wether to use dgraph in production - it seems a bit unstable/cumbersome to deploy and manage especially if there might be dataloss or errors like the described ones, which can only be “solved” by rm -rf. We thought of deploying it to 8gb ram machines with 4 cores. This is just a part of the whole dataset and it must be synchronized every now and then - perhaps not possible on this kind of machine.

alpha_1 | I0411 21:59:36.575115 14 draft.go:136] Operation started with id: opRollup
alpha_1 | I0411 22:04:30.501918 14 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
alpha_1 | I0411 22:04:30.501976 14 log.go:34] Running for level: 0
alpha_1 | I0411 22:04:30.860490 14 log.go:34] LOG Compact 0->1, del 6 tables, add 1 tables, took 358.500295ms
alpha_1 | I0411 22:04:30.860523 14 log.go:34] Compaction for level: 0 DONE
alpha_1 | I0411 22:07:59.471448 14 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
alpha_1 | I0411 22:07:59.471495 14 log.go:34] Running for level: 0
alpha_1 | I0411 22:08:00.875596 14 log.go:34] LOG Compact 0->1, del 6 tables, add 4 tables, took 1.404088412s
alpha_1 | I0411 22:08:00.875636 14 log.go:34] Compaction for level: 0 DONE
alpha_1 | I0411 22:11:08.471385 14 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
alpha_1 | I0411 22:11:08.471433 14 log.go:34] Running for level: 0
alpha_1 | I0411 22:11:11.284801 14 log.go:34] LOG Compact 0->1, del 9 tables, add 7 tables, took 2.813354703s
alpha_1 | I0411 22:11:11.284847 14 log.go:34] Compaction for level: 0 DONE
alpha_1 | I0411 22:14:37.470818 14 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
alpha_1 | I0411 22:14:37.470934 14 log.go:34] Running for level: 0
alpha_1 | I0411 22:14:40.903792 14 log.go:34] LOG Compact 0->1, del 12 tables, add 10 tables, took 3.432809903s
alpha_1 | I0411 22:14:40.903836 14 log.go:34] Compaction for level: 0 DONE
alpha_1 | I0411 22:15:18.764163 14 draft.go:523] Creating snapshot at index: 23470. ReadTs: 33307.
zero_1 | W0411 22:15:25.388043 16 node.go:671] [0x1] Read index context timed out
zero_1 | W0411 22:15:27.407629 16 node.go:671] [0x1] Read index context timed out
zero_1 | I0411 22:15:27.934150 16 oracle.go:107] Purged below ts:33307, len(o.commits):80, len(o.rowCommit):622962
zero_1 | W0411 22:15:27.934243 16 raft.go:733] Raft.Ready took too long to process: Timer Total: 4.547s. Breakdown: [{proposals 4.547s} {disk 0s} {sync 0s} {advance 0s}]. Num entries: 1. MustSync: true
zero_1 | I0411 22:15:28.088899 16 oracle.go:107] Purged below ts:33307, len(o.commits):80, len(o.rowCommit):622962
zero_1 | I0411 22:15:33.284670 16 raft.go:616] Writing snapshot at index: 11887, applied mark: 12060
alpha_1 | I0411 22:18:40.470942 14 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
alpha_1 | I0411 22:18:40.470994 14 log.go:34] Running for level: 0
alpha_1 | I0411 22:18:40.766790 14 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:}
alpha_1 | I0411 22:18:40.766842 14 log.go:34] Running for level: 0
alpha_1 | I0411 22:18:41.137025 14 log.go:34] LOG Compact 0->1, del 6 tables, add 2 tables, took 370.164792ms
alpha_1 | I0411 22:18:41.137073 14 log.go:34] Compaction for level: 0 DONE
alpha_1 | I0411 22:18:46.234204 14 log.go:34] LOG Compact 0->1, del 15 tables, add 13 tables, took 5.763193925s
alpha_1 | I0411 22:18:46.234250 14 log.go:34] Compaction for level: 0 DONE

Unbenannt
Unbenannt577Ă—1052 8.96 KB

3

Try the new feature (you gonna need more memory on docker, something like 14GB+ to run 21 million RDFs) called ludicrous mode (eventually consistent writes). It hasn’t been released yet, use it sparingly. And disable it after you have loaded the dataset.

This mode is not recommended for financial systems.

docker pull dgraph/dgraph:master

docker run -d -p 5080:5080 -p 6080:6080 -p 8080:8080 -p 9080:9080 -p 8000:8000 -v ~/dgraph:/dgraph --name dgraph dgraph/dgraph:master dgraph zero --ludicrous_mode

docker exec -d dgraph dgraph alpha --zero localhost:5080 --ludicrous_mode

docker exec -it dgraph sh

AND

curl --progress-bar -LS -o 21million.rdf.gz "https://github.com/dgraph-io/benchmarks/blob/master/data/release/21million.rdf.gz?raw=true"
curl --progress-bar -LS -o release.schema "https://github.com/dgraph-io/benchmarks/blob/master/data/release/release.schema?raw=true"

ls

Then

dgraph live -f 21million.rdf.gz -s release.schema --conc=100 --batch=10000

Decrease the values of conc and batch according to your machine (do some testing of parameters to find out which is the best)

4

Hey thankyou for your answer - i will try this out.
Happy Easter to all badgers, ratels, gophers and dgraphers!

2 Likes
5

This is a temporary error. It just indicates that Zero leadership changed and Alpha needs to connect to a new Zero leader.

Again, a temporary error as it says.

This one shows that Zero leadership changed. So, Alpha canceled the Zero stream which spits out this error log. It will then reconnect to the new Zero leader.

Dgraph would replay the Raft WAL logs on a crash, that’s normal. Deleting them with a rm -rf would cause issues – unless you’re just starting a new cluster.

I’m not seeing any logs here which resembles a crash – it sounds like you might be going OOM or something. Also, any reason to not use 20.03, which is the latest release? This looks like an older version.

CC: @Paras @martinmr