Bulk load fails

I’m trying to do bulk load but running into this

Error on Zero
I1212 18:21:11.291695 1 assign.go:41] Updated Lease id: 18446055125946300485. Txn Ts: 110001
W1212 18:21:12.993017 1 node.go:669] [0x1] Read index context timed out
W1212 18:22:02.253909 1 raft.go:729] Raft.Ready took too long to process: Timer Total: 280ms. Breakdown: [{disk 277ms} {advance 1ms} {proposals 0s}]. Num entries: 0. MustSync: false
W1212 18:22:05.934343 1 raft.go:729] Raft.Ready took too long to process: Timer Total: 299ms. Breakdown: [{disk 146ms} {proposals 47ms} {advance 10ms}]. Num entries: 0. MustSync: false
W1212 18:22:13.235066 1 raft.go:729] Raft.Ready took too long to process: Timer Total: 1.204s. Breakdown: [{disk 965ms} {proposals 212ms} {advance 8ms}]. Num entries: 0. MustSync: false
W1212 18:22:16.532623 1 node.go:669] [0x1] Read index context timed out
W1212 18:22:27.271759 1 node.go:669] [0x1] Read index context timed out
W1212 18:22:21.670279 1 raft.go:729] Raft.Ready took too long to process: Timer Total: 831ms. Breakdown: [{disk 803ms} {proposals 24ms} {advance 0s}]. Num entries: 0. MustSync: false
W1212 18:22:49.268878 1 node.go:669] [0x1] Read index context timed out
W1212 18:23:01.828706 1 node.go:669] [0x1] Read index context timed out
W1212 18:23:04.633381 1 raft.go:729] Raft.Ready took too long to process: Timer Total: 5.149s. Breakdown: [{disk 5.127s} {proposals 19ms} {advance 1ms}]. Num entries: 0. MustSync: false
W1212 18:23:04.945402 1 raft.go:729] Raft.Ready took too long to process: Timer Total: 224ms. Breakdown: [{disk 96ms} {advance 81ms} {proposals 27ms}]. Num entries: 0. MustSync: false
W1212 18:23:51.959628 1 node.go:669] [0x1] Read index context timed out
E1212 18:24:19.559844 1 node.go:654] Error while trying to call ReadIndex: context deadline exceeded
E1212 18:24:34.035801 1 node.go:707] [0x1] While trying to do lin read index: context deadline exceeded

This is my dgraph zero
Dgraph version : v1.1.0
Dgraph SHA-256 : 7d4294a80f74692695467e2cf17f74648c18087ed7057d798f40e1d3a31d2095
Commit SHA-1 : ef7cdb28
Commit timestamp : 2019-09-04 00:12:51 -0700
Branch : HEAD
Go version : go1.12.7

When running this, I have one instance of zero, no alpha running at that time.

The command line
docker exec -it dgraph dgraph bulk -f mail.rdf.gz -s schema.txt --map_shards=8 --reduce_shards=4 --http localhost:8000 --zero=localhost:5080

This is running on my mac book pro, with 32G memory.

This is output from the bulk loader
[Decoder]: Using assembly version of decoder
I1212 18:21:29.948590 24 init.go:98]

Dgraph version : v1.1.0
Dgraph SHA-256 : 7d4294a80f74692695467e2cf17f74648c18087ed7057d798f40e1d3a31d2095
Commit SHA-1 : ef7cdb28
Commit timestamp : 2019-09-04 00:12:51 -0700
Branch : HEAD
Go version : go1.12.7

Licensed variously under the Apache Public License 2.0 and Dgraph Community License.
Copyright 2015-2018 Dgraph Labs, Inc.

{
“DataFiles”: “mail.rdf.gz”,
“DataFormat”: “”,
“SchemaFile”: “schema.txt”,
“OutDir”: “./out”,
“ReplaceOutDir”: false,
“TmpDir”: “tmp”,
“NumGoroutines”: 2,
“MapBufSize”: 67108864,
“SkipMapPhase”: false,
“CleanupTmp”: true,
“NumReducers”: 1,
“Version”: false,
“StoreXids”: false,
“ZeroAddr”: “localhost:5080”,
“HttpAddr”: “localhost:8000”,
“IgnoreErrors”: false,
“CustomTokenizers”: “”,
“NewUids”: false,
“MapShards”: 8,
“ReduceShards”: 4
}
Connecting to zero at localhost:5080
Processing file (1 out of 1): mail.rdf.gz
[18:21:31Z] MAP 01s nquad_count:110.6k err_count:0.000 nquad_speed:109.9k/sec edge_count:185.7k edge_speed:184.5k/sec
[18:21:32Z] MAP 02s nquad_count:250.2k err_count:0.000 nquad_speed:124.7k/sec edge_count:420.3k edge_speed:209.4k/sec
[18:21:33Z] MAP 03s nquad_count:371.5k err_count:0.000 nquad_speed:123.5k/sec edge_count:623.8k edge_speed:207.4k/sec
[18:21:34Z] MAP 04s nquad_count:514.9k err_count:0.000 nquad_speed:128.4k/sec edge_count:864.6k edge_speed:215.6k/sec
[18:21:35Z] MAP 05s nquad_count:653.5k err_count:0.000 nquad_speed:130.4k/sec edge_count:1.097M edge_speed:219.1k/sec
[18:21:36Z] MAP 06s nquad_count:785.9k err_count:0.000 nquad_speed:130.8k/sec edge_count:1.320M edge_speed:219.6k/sec
[18:21:37Z] MAP 07s nquad_count:918.0k err_count:0.000 nquad_speed:130.9k/sec edge_count:1.542M edge_speed:219.9k/sec
[18:21:38Z] MAP 08s nquad_count:1.034M err_count:0.000 nquad_speed:129.1k/sec edge_count:1.736M edge_speed:216.7k/sec
[18:21:39Z] MAP 09s nquad_count:1.156M err_count:0.000 nquad_speed:128.3k/sec edge_count:1.941M edge_speed:215.4k/sec
GC: 19. InUse: 719 MB. Idle: 53 MB
[18:21:40Z] MAP 10s nquad_count:1.284M err_count:0.000 nquad_speed:128.3k/sec edge_count:2.156M edge_speed:215.4k/sec
[18:21:41Z] MAP 11s nquad_count:1.398M err_count:0.000 nquad_speed:126.9k/sec edge_count:2.347M edge_speed:213.1k/sec
[18:21:42Z] MAP 12s nquad_count:1.563M err_count:0.000 nquad_speed:130.1k/sec edge_count:2.625M edge_speed:218.5k/sec
[18:21:43Z] MAP 13s nquad_count:1.686M err_count:0.000 nquad_speed:129.6k/sec edge_count:2.832M edge_speed:217.6k/sec
[18:21:44Z] MAP 14s nquad_count:1.790M err_count:0.000 nquad_speed:127.7k/sec edge_count:3.006M edge_speed:214.5k/sec
[18:21:45Z] MAP 15s nquad_count:1.949M err_count:0.000 nquad_speed:129.8k/sec edge_count:3.273M edge_speed:218.0k/sec
[18:21:46Z] MAP 16s nquad_count:2.068M err_count:0.000 nquad_speed:129.1k/sec edge_count:3.472M edge_speed:216.8k/sec
[18:21:47Z] MAP 17s nquad_count:2.190M err_count:0.000 nquad_speed:128.7k/sec edge_count:3.677M edge_speed:216.1k/sec
[18:21:48Z] MAP 18s nquad_count:2.344M err_count:0.000 nquad_speed:130.1k/sec edge_count:3.936M edge_speed:218.5k/sec
[18:21:49Z] MAP 19s nquad_count:2.470M err_count:0.000 nquad_speed:129.9k/sec edge_count:4.148M edge_speed:218.1k/sec
GC: 23. InUse: 1.5 GB. Idle: 44 MB
[18:21:50Z] MAP 20s nquad_count:2.558M err_count:0.000 nquad_speed:127.7k/sec edge_count:4.295M edge_speed:214.5k/sec
[18:21:51Z] MAP 21s nquad_count:2.710M err_count:0.000 nquad_speed:128.9k/sec edge_count:4.551M edge_speed:216.5k/sec
[18:21:52Z] MAP 22s nquad_count:2.843M err_count:0.000 nquad_speed:129.1k/sec edge_count:4.774M edge_speed:216.8k/sec
[18:21:53Z] MAP 23s nquad_count:2.965M err_count:0.000 nquad_speed:128.8k/sec edge_count:4.980M edge_speed:216.3k/sec
[18:21:54Z] MAP 24s nquad_count:3.050M err_count:0.000 nquad_speed:127.0k/sec edge_count:5.122M edge_speed:213.2k/sec
[18:21:55Z] MAP 25s nquad_count:3.151M err_count:0.000 nquad_speed:125.9k/sec edge_count:5.292M edge_speed:211.5k/sec
[18:21:56Z] MAP 26s nquad_count:3.244M err_count:0.000 nquad_speed:124.7k/sec edge_count:5.448M edge_speed:209.3k/sec
[18:21:57Z] MAP 27s nquad_count:3.348M err_count:0.000 nquad_speed:123.9k/sec edge_count:5.621M edge_speed:208.0k/sec
[18:21:58Z] MAP 28s nquad_count:3.440M err_count:0.000 nquad_speed:122.7k/sec edge_count:5.776M edge_speed:206.1k/sec
[18:21:59Z] MAP 29s nquad_count:3.528M err_count:0.000 nquad_speed:121.5k/sec edge_count:5.923M edge_speed:204.1k/sec
GC: 24. InUse: 2.0 GB. Idle: 3.8 MB
[18:22:00Z] MAP 30s nquad_count:3.596M err_count:0.000 nquad_speed:119.7k/sec edge_count:6.038M edge_speed:201.1k/sec
[18:22:01Z] MAP 31s nquad_count:3.682M err_count:0.000 nquad_speed:118.7k/sec edge_count:6.183M edge_speed:199.3k/sec
[18:22:02Z] MAP 32s nquad_count:3.725M err_count:0.000 nquad_speed:116.2k/sec edge_count:6.255M edge_speed:195.1k/sec
[18:22:03Z] MAP 33s nquad_count:3.729M err_count:0.000 nquad_speed:112.5k/sec edge_count:6.262M edge_speed:188.8k/sec
[18:22:04Z] MAP 34s nquad_count:3.752M err_count:0.000 nquad_speed:109.8k/sec edge_count:6.301M edge_speed:184.3k/sec
[18:22:05Z] MAP 35s nquad_count:3.760M err_count:0.000 nquad_speed:106.8k/sec edge_count:6.313M edge_speed:179.3k/sec
[18:22:06Z] MAP 36s nquad_count:3.766M err_count:0.000 nquad_speed:104.0k/sec edge_count:6.324M edge_speed:174.6k/sec
[18:22:07Z] MAP 37s nquad_count:3.783M err_count:0.000 nquad_speed:101.4k/sec edge_count:6.352M edge_speed:170.3k/sec
[18:22:08Z] MAP 38s nquad_count:3.788M err_count:0.000 nquad_speed:98.86k/sec edge_count:6.360M edge_speed:166.0k/sec
GC: 25. InUse: 1.7 GB. Idle: 545 MB
[18:22:09Z] MAP 39s nquad_count:3.788M err_count:0.000 nquad_speed:95.96k/sec edge_count:6.360M edge_speed:161.1k/sec
[18:22:12Z] MAP 42s nquad_count:3.790M err_count:0.000 nquad_speed:89.28k/sec edge_count:6.363M edge_speed:149.9k/sec
[18:22:13Z] MAP 43s nquad_count:3.790M err_count:0.000 nquad_speed:86.82k/sec edge_count:6.364M edge_speed:145.8k/sec
[18:22:16Z] MAP 46s nquad_count:3.790M err_count:0.000 nquad_speed:81.07k/sec edge_count:6.364M edge_speed:136.1k/sec
[18:22:18Z] MAP 48s nquad_count:3.790M err_count:0.000 nquad_speed:78.69k/sec edge_count:6.364M edge_speed:132.1k/sec
GC: 25. InUse: 1.7 GB. Idle: 543 MB
[18:22:19Z] MAP 51s nquad_count:3.790M err_count:0.000 nquad_speed:73.87k/sec edge_count:6.364M edge_speed:124.0k/sec
[18:22:49Z] MAP 01m19s nquad_count:3.790M err_count:0.000 nquad_speed:47.68k/sec edge_count:6.364M edge_speed:80.05k/sec
[18:22:50Z] MAP 01m21s nquad_count:3.790M err_count:0.000 nquad_speed:46.76k/sec edge_count:6.365M edge_speed:78.51k/sec
GC: 26. InUse: 1.7 GB. Idle: 613 MB
[18:22:58Z] MAP 01m32s nquad_count:3.793M err_count:0.000 nquad_speed:41.05k/sec edge_count:6.365M edge_speed:68.87k/sec
[18:23:19Z] MAP 01m49s nquad_count:3.793M err_count:0.000 nquad_speed:34.73k/sec edge_count:6.369M edge_speed:58.32k/sec
[18:23:31Z] MAP 02m01s nquad_count:3.793M err_count:0.000 nquad_speed:31.26k/sec edge_count:6.369M edge_speed:52.50k/sec
[18:23:55Z] MAP 02m25s nquad_count:3.793M err_count:0.000 nquad_speed:26.13k/sec edge_count:6.369M edge_speed:43.87k/sec
[18:23:56Z] MAP 02m26s nquad_count:3.793M err_count:0.000 nquad_speed:25.94k/sec edge_count:6.369M edge_speed:43.55k/sec
[18:23:57Z] MAP 02m29s nquad_count:3.794M err_count:0.000 nquad_speed:25.34k/sec edge_count:6.371M edge_speed:42.54k/sec
GC: 27. InUse: 1.7 GB. Idle: 613 MB
[18:24:22Z] MAP 02m52s nquad_count:3.794M err_count:0.000 nquad_speed:21.95k/sec edge_count:6.371M edge_speed:36.85k/sec
[18:24:27Z] MAP 02m58s nquad_count:3.794M err_count:0.000 nquad_speed:21.26k/sec edge_count:6.371M edge_speed:35.69k/sec
[18:24:31Z] MAP 03m01s nquad_count:3.795M err_count:0.000 nquad_speed:20.86k/sec edge_count:6.372M edge_speed:35.02k/sec

bulk loader would use a large memory,if your dataset is too large,it maybe occur error to fail

Hey @guoweis, I would like to know few things to proceed further:

  • What was the error at client side when bulk loader failed? It is not clear from logs.
  • How much data are you trying to insert(size, count)?
  • If possible please provide memory/cpu usage before failure.

We have done some optimisations in bulk loader recently, please try to run it on master(or v1.1.1-rc2) and let us know if the issue still occurs.