Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Data races with export #3693

Closed
danielmai opened this issue Jul 19, 2019 · 1 comment · Fixed by #3697
Closed

Data races with export #3693

danielmai opened this issue Jul 19, 2019 · 1 comment · Fixed by #3697
Labels
kind/bug Something is broken.

Comments

@danielmai
Copy link
Contributor

If you suspect this could be a bug, follow the template.

  • What version of Dgraph are you using?
Dgraph version   : v1.0.12-rc3-605-ge5791c37e
Commit SHA-1     : e5791c37e
Commit timestamp : 2019-07-17 18:32:41 -0700
Branch           : master
Go version       : go1.12.5

  • Have you tried reproducing the issue with latest release?
    Only tested on master for now.

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

  1. Build Dgraph with race detector.
make BUILD_RACE=Y install
  1. Two-group cluster with 6 Alphas, 3 Zeros, --replicas=3.
./compose -a 6 -z 3
  1. Run Flock.
./flock -a ":9180,:9182,:9183,:9184,:9185,:9186"
  1. Export data.
docker exec alpha1 curl localhost:8180/admin/export
  • Expected behaviour and actual result.
  1. I get an empty response from curl, but according to the Alpha logs the export succeeded so I expected a "Success" message:
$ docker exec -it alpha1 curl localhost:8180/admin/export
curl: (52) Empty reply from server
  1. The race detector found a lot of data races during the export. The full logs from one of the Alphas is attached in alpha1.log.
@danielmai danielmai added the kind/bug Something is broken. label Jul 19, 2019
@danielmai
Copy link
Contributor Author

Running with the export fix PR (#3682) shows fewer data races.

alpha1-pr3682.log 
[Decoder]: Using assembly version of decoder
I0719 01:00:00.502839       1 init.go:93] 

Dgraph version   : v1.0.12-rc3-611-g120156b9c
Commit SHA-1     : 120156b9c
Commit timestamp : 2019-07-17 16:19:06 -0700
Branch           : gitlw/fix_export
Go version       : go1.12.5

For Dgraph official documentation, visit https://docs.dgraph.io.
For discussions about Dgraph     , visit https://discuss.dgraph.io.
To say hi to the community       , visit https://dgraph.slack.com.

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


I0719 01:00:00.502951       1 run.go:502] x.Config: {PortOffset:100 QueryEdgeLimit:1000000 NormalizeNodeLimit:10000}
I0719 01:00:00.503015       1 run.go:503] x.WorkerConfig: {ExportPath:export NumPendingProposals:256 Tracing:1 MyAddr:alpha1:7180 ZeroAddr:zero1:5180 RaftId:0 WhiteListedIPRanges:[] MaxRetries:-1 StrictMutations:false AclEnabled:false AbortOlderThan:5m0s SnapshotAfter:10000}
I0719 01:00:00.503103       1 run.go:504] edgraph.Config: {PostingDir:p BadgerTables:mmap BadgerVlog:mmap WALDir:w MutationsMode:0 AuthToken: AllottedMemory:1024 HmacSecret:[] AccessJwtTtl:0s RefreshJwtTtl:0s AclRefreshInterval:0s}
I0719 01:00:00.503210       1 server.go:125] Setting Badger table load option: mmap
I0719 01:00:00.503239       1 server.go:137] Setting Badger value log load option: mmap
I0719 01:00:00.503279       1 server.go:165] Opening write-ahead log BadgerDB with options: {Dir:w ValueDir:w SyncWrites:false TableLoadingMode:1 ValueLogLoadingMode:2 NumVersionsToKeep:1 ReadOnly:false Truncate:true Logger:0x33f24a0 MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:65500 NumMemtables:5 NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:10000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 managedTxns:false maxBatchCount:0 maxBatchSize:0}
I0719 01:00:02.283557       1 log.go:34] All 3 tables opened in 1.761s
I0719 01:00:02.287589       1 log.go:34] Replaying file id: 434 at offset: 1121284
I0719 01:00:02.287801       1 log.go:34] Replay took: 169.757µs
I0719 01:00:02.287875       1 log.go:34] Replaying file id: 435 at offset: 0
I0719 01:00:02.741392       1 log.go:34] Replay took: 453.444344ms
I0719 01:00:02.741564       1 log.go:34] Replaying file id: 436 at offset: 0
I0719 01:00:02.855644       1 log.go:34] Replay took: 114.00553ms
I0719 01:00:02.856852       1 server.go:125] Setting Badger table load option: mmap
I0719 01:00:02.856901       1 server.go:137] Setting Badger value log load option: mmap
I0719 01:00:02.856977       1 server.go:178] Opening postings BadgerDB with options: {Dir:p ValueDir:p SyncWrites:false TableLoadingMode:2 ValueLogLoadingMode:2 NumVersionsToKeep:2147483647 ReadOnly:false Truncate:true Logger:0x33f24a0 MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1024 NumMemtables:5 NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:1000000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 managedTxns:false maxBatchCount:0 maxBatchSize:0}
I0719 01:00:06.108950       1 log.go:34] 4 tables out of 8 opened in 3.246s
I0719 01:00:08.453429       1 log.go:34] All 8 tables opened in 5.591s
I0719 01:00:08.458028       1 log.go:34] Replaying file id: 18 at offset: 10342168
I0719 01:00:11.652622       1 log.go:34] Replay took: 3.19454906s
I0719 01:00:11.655807       1 worker.go:81] Worker listening at address: [::]:7180
I0719 01:00:11.656138       1 groups.go:98] Current Raft Id: 0x1
I0719 01:00:11.656295       1 groups.go:579] No healthy Zero leader found. Trying to find a Zero leader...
I0719 01:00:11.656303       1 run.go:414] gRPC server started.  Listening on port 9180
I0719 01:00:11.656398       1 run.go:415] HTTP server started.  Listening on port 8180
I0719 01:00:11.757283       1 pool.go:148] CONNECTED to zero1:5180
I0719 01:00:11.767969       1 groups.go:616] Found connection to leader: zero1:5180
I0719 01:00:11.773111       1 groups.go:121] Connected to group zero. Assigned group: 0
I0719 01:00:11.773178       1 groups.go:123] Raft Id after connection to Zero: 0x1
I0719 01:00:11.773976       1 pool.go:148] CONNECTED to alpha6:7186
I0719 01:00:11.774792       1 pool.go:148] CONNECTED to alpha4:7184
I0719 01:00:11.775711       1 pool.go:148] CONNECTED to alpha5:7185
I0719 01:00:11.776954       1 pool.go:148] CONNECTED to alpha3:7183
I0719 01:00:11.777919       1 pool.go:148] CONNECTED to alpha2:7182
I0719 01:00:11.778987       1 pool.go:148] CONNECTED to zero3:5183
I0719 01:00:11.780255       1 pool.go:148] CONNECTED to zero2:5182
W0719 01:00:11.780224       1 pool.go:237] Connection lost with alpha3:7183. Error: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 172.19.0.10:7183: connect: connection refused"
I0719 01:00:11.780666       1 draft.go:75] Node ID: 0x1 with GroupID: 1
I0719 01:00:11.781615       1 node.go:143] Setting raft.Config to: &{ID:1 peers:[] learners:[] ElectionTick:100 HeartbeatTick:1 Storage:0xc0005a6ff0 Applied:1085345 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x33f24a0 DisableProposalForwarding:false}
W0719 01:00:11.781985       1 pool.go:237] Connection lost with alpha2:7182. Error: rpc error: code = Unavailable desc = all SubConns are in TransientFailure, latest connection error: connection error: desc = "transport: Error while dialing dial tcp 172.19.0.9:7182: connect: connection refused"
I0719 01:00:11.787698       1 node.go:301] Found Snapshot.Metadata: {ConfState:{Nodes:[1 2 3] Learners:[] XXX_unrecognized:[]} Index:1085345 Term:3 XXX_unrecognized:[]}
I0719 01:00:11.788279       1 node.go:312] Found hardstate: {Term:8 Vote:1 Commit:1086690 XXX_unrecognized:[]}
I0719 01:00:18.416771       1 node.go:321] Group 1 found 1346 entries
I0719 01:00:18.416962       1 draft.go:1360] Restarting node for group: 1
I0719 01:00:18.417172       1 node.go:180] Setting conf state to nodes:1 nodes:2 nodes:3 
I0719 01:00:24.869136       1 storage.go:261] Setting first index: 1085346
I0719 01:00:24.874359       1 log.go:34] 1 became follower at term 8
I0719 01:00:24.877485       1 log.go:34] newRaft 1 [peers: [1,2,3], term: 8, commit: 1086690, applied: 1085345, lastindex: 1086690, lastterm: 8]
I0719 01:00:24.877678       1 draft.go:1380] Restart node complete
I0719 01:00:24.878300       1 groups.go:141] Server is ready
I0719 01:00:24.878933       1 groups.go:727] Got address of a Zero leader: zero1:5180
I0719 01:00:24.879017       1 draft.go:741] Found Raft progress: 1086690
I0719 01:00:24.879754       1 groups.go:740] Starting a new membership stream receive from zero1:5180.
I0719 01:00:24.883321       1 groups.go:757] Received first state update from Zero: counter:578534 groups:<key:1 value:<members:<key:1 value:<id:1 group_id:1 addr:"alpha1:7180" leader:true last_update:1563497356 > > members:<key:2 value:<id:2 group_id:1 addr:"alpha2:7182" > > members:<key:3 value:<id:3 group_id:1 addr:"alpha3:7183" last_update:1563496541 > > tablets:<key:"dgraph.type" value:<group_id:1 predicate:"dgraph.type" space:40 > > tablets:<key:"friends_count" value:<group_id:1 predicate:"friends_count" space:41906344 > > tablets:<key:"hashtags" value:<group_id:1 predicate:"hashtags" space:15442361 > > tablets:<key:"profile_image_url" value:<group_id:1 predicate:"profile_image_url" space:76474569 > > tablets:<key:"screen_name" value:<group_id:1 predicate:"screen_name" space:102592873 > > tablets:<key:"user_id" value:<group_id:1 predicate:"user_id" space:101244650 > > tablets:<key:"user_name" value:<group_id:1 predicate:"user_name" space:113384339 > > tablets:<key:"verified" value:<group_id:1 predicate:"verified" space:127672 > > snapshot_ts:1153382 checksum:8916989309327556601 > > groups:<key:2 value:<members:<key:4 value:<id:4 group_id:2 addr:"alpha4:7184" last_update:1563474581 > > members:<key:5 value:<id:5 group_id:2 addr:"alpha5:7185" leader:true last_update:1563498024 > > members:<key:6 value:<id:6 group_id:2 addr:"alpha6:7186" > > tablets:<key:"author" value:<group_id:2 predicate:"author" space:45567400 > > tablets:<key:"created_at" value:<group_id:2 predicate:"created_at" space:49137489 > > tablets:<key:"description" value:<group_id:2 predicate:"description" space:75049298 > > tablets:<key:"id_str" value:<group_id:2 predicate:"id_str" space:75351842 > > tablets:<key:"mention" value:<group_id:2 predicate:"mention" space:28171517 > > tablets:<key:"message" value:<group_id:2 predicate:"message" space:111611319 > > tablets:<key:"profile_banner_url" value:<group_id:2 predicate:"profile_banner_url" space:64052412 > > tablets:<key:"retweet" value:<group_id:2 predicate:"retweet" space:39511394 > > tablets:<key:"urls" value:<group_id:2 predicate:"urls" space:7628544 > > snapshot_ts:1153882 checksum:3292051695930804623 > > zeros:<key:1 value:<id:1 addr:"zero1:5180" leader:true > > zeros:<key:2 value:<id:2 addr:"zero2:5182" > > zeros:<key:3 value:<id:3 addr:"zero3:5183" > > maxLeaseId:1390000 maxTxnTs:1190000 maxRaftId:6 cid:"ddee998f-cd7f-4f54-a1c8-b2ccb200fc4e" 
I0719 01:00:25.879449       1 groups.go:172] Done informing Zero about the 8 tablets I have
I0719 01:00:25.879944       1 groups.go:194] Skipping initial schema upsert for predicate dgraph.type
I0719 01:00:28.561304       1 log.go:34] 1 is starting a new election at term 8
I0719 01:00:28.561482       1 log.go:34] 1 became pre-candidate at term 8
I0719 01:00:28.561576       1 log.go:34] 1 received MsgPreVoteResp from 1 at term 8
I0719 01:00:28.569558       1 log.go:34] 1 [logterm: 8, index: 1086690] sent MsgPreVote request to 2 at term 8
I0719 01:00:28.576842       1 log.go:34] 1 [logterm: 8, index: 1086690] sent MsgPreVote request to 3 at term 8
I0719 01:00:28.580901       1 node.go:249] RaftComm: [0x1] Sending message of type MsgPreVote to 0x2
I0719 01:00:28.581104       1 node.go:249] RaftComm: [0x1] Sending message of type MsgPreVote to 0x3
I0719 01:00:28.781280       1 raft_server.go:233] RaftComm: [0x1] Received msg of type: MsgPreVote from 0x3
I0719 01:00:28.798403       1 log.go:34] 1 [logterm: 8, index: 1086690, vote: 1] cast MsgPreVote for 3 [logterm: 8, index: 1086690] at term 8
I0719 01:00:28.799073       1 node.go:249] RaftComm: [0x1] Sending message of type MsgPreVoteResp to 0x3
I0719 01:00:29.595575       1 raft_server.go:233] RaftComm: [0x1] Received msg of type: MsgPreVoteResp from 0x3
I0719 01:00:29.595724       1 log.go:34] 1 received MsgPreVoteResp from 3 at term 8
I0719 01:00:29.595850       1 log.go:34] 1 [quorum:2] has received 2 MsgPreVoteResp votes and 0 vote rejections
I0719 01:00:29.602882       1 log.go:34] 1 became candidate at term 9
I0719 01:00:29.602952       1 log.go:34] 1 received MsgVoteResp from 1 at term 9
I0719 01:00:29.609557       1 log.go:34] 1 [logterm: 8, index: 1086690] sent MsgVote request to 2 at term 9
I0719 01:00:29.610073       1 raft_server.go:233] RaftComm: [0x1] Received msg of type: MsgVote from 0x3
I0719 01:00:29.616903       1 log.go:34] 1 [logterm: 8, index: 1086690] sent MsgVote request to 3 at term 9
I0719 01:00:29.623790       1 node.go:249] RaftComm: [0x1] Sending message of type MsgVote to 0x2
I0719 01:00:29.623881       1 node.go:249] RaftComm: [0x1] Sending message of type MsgVote to 0x3
I0719 01:00:29.624767       1 log.go:34] 1 [logterm: 8, index: 1086690, vote: 1] rejected MsgVote from 3 [logterm: 8, index: 1086690] at term 9
I0719 01:00:29.625444       1 node.go:249] RaftComm: [0x1] Sending message of type MsgVoteResp to 0x3
I0719 01:00:29.628858       1 raft_server.go:233] RaftComm: [0x1] Received msg of type: MsgVoteResp from 0x3
I0719 01:00:29.629051       1 log.go:34] 1 received MsgVoteResp rejection from 3 at term 9
I0719 01:00:29.629176       1 log.go:34] 1 [quorum:2] has received 1 MsgVoteResp votes and 1 vote rejections
I0719 01:00:29.809727       1 log.go:34] 1 became follower at term 9
I0719 01:00:29.816656       1 log.go:34] raft.node: 1 elected leader 3 at term 9
I0719 01:00:30.599072       1 raft_server.go:233] RaftComm: [0x1] Received msg of type: MsgPreVoteResp from 0x2
I0719 01:00:30.599350       1 raft_server.go:233] RaftComm: [0x1] Received msg of type: MsgVoteResp from 0x2
I0719 01:01:41.225948       1 export.go:662] Got readonly ts from Zero: 1190001
I0719 01:01:41.226063       1 export.go:666] Requesting export for groups: [2 1]
I0719 01:01:41.226358       1 export.go:639] Sending export request to group: 2, addr: alpha5:7185
I0719 01:01:41.226367       1 export.go:427] Export requested at 1190001.
I0719 01:01:41.368523       1 export.go:433] Running export for group 1 at timestamp 1190001.
I0719 01:01:41.369113       1 export.go:454] Exporting data for group: 1 at /data/alpha1/export/dgraph.r1190001.u0719.0101/g01.rdf.gz
I0719 01:01:41.370363       1 export.go:465] Exporting schema for group: 1 at /data/alpha1/export/dgraph.r1190001.u0719.0101/g01.schema.gz
==================
WARNING: DATA RACE
Write at 0x00c0038cd860 by goroutine 358:
  github.com/dgraph-io/dgraph/worker.export.func3()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:529 +0x88a
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:190 +0x53b
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:233 +0x446
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:336 +0x76

Previous write at 0x00c0038cd860 by goroutine 352:
  github.com/dgraph-io/dgraph/worker.export.func3()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:529 +0x88a
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:190 +0x53b
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:233 +0x446
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:336 +0x76

Goroutine 358 (running) created at:
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:333 +0x245
  github.com/dgraph-io/dgraph/worker.export()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:594 +0x11f6
  github.com/dgraph-io/dgraph/worker.handleExportOverNetwork()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:631 +0x4dc
  github.com/dgraph-io/dgraph/worker.ExportOverNetwork.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:677 +0x197

Goroutine 352 (running) created at:
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:333 +0x245
  github.com/dgraph-io/dgraph/worker.export()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:594 +0x11f6
  github.com/dgraph-io/dgraph/worker.handleExportOverNetwork()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:631 +0x4dc
  github.com/dgraph-io/dgraph/worker.ExportOverNetwork.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:677 +0x197
==================
==================
WARNING: DATA RACE
Write at 0x00c0038cd860 by goroutine 355:
  github.com/dgraph-io/dgraph/worker.export.func3()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:529 +0x88a
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:190 +0x53b
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:233 +0x446
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:336 +0x76

Previous write at 0x00c0038cd860 by goroutine 352:
  github.com/dgraph-io/dgraph/worker.export.func3()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:529 +0x88a
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:190 +0x53b
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:233 +0x446
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:336 +0x76

Goroutine 355 (running) created at:
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:333 +0x245
  github.com/dgraph-io/dgraph/worker.export()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:594 +0x11f6
  github.com/dgraph-io/dgraph/worker.handleExportOverNetwork()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:631 +0x4dc
  github.com/dgraph-io/dgraph/worker.ExportOverNetwork.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:677 +0x197

Goroutine 352 (running) created at:
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:333 +0x245
  github.com/dgraph-io/dgraph/worker.export()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:594 +0x11f6
  github.com/dgraph-io/dgraph/worker.handleExportOverNetwork()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:631 +0x4dc
  github.com/dgraph-io/dgraph/worker.ExportOverNetwork.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:677 +0x197
==================
==================
WARNING: DATA RACE
Write at 0x00c0038cd860 by goroutine 356:
  github.com/dgraph-io/dgraph/worker.export.func3()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:529 +0x88a
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:190 +0x53b
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:233 +0x446
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:336 +0x76

Previous write at 0x00c0038cd860 by goroutine 352:
  github.com/dgraph-io/dgraph/worker.export.func3()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:529 +0x88a
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:190 +0x53b
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).produceKVs()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:233 +0x446
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:336 +0x76

Goroutine 356 (running) created at:
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:333 +0x245
  github.com/dgraph-io/dgraph/worker.export()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:594 +0x11f6
  github.com/dgraph-io/dgraph/worker.handleExportOverNetwork()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:631 +0x4dc
  github.com/dgraph-io/dgraph/worker.ExportOverNetwork.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:677 +0x197

Goroutine 352 (running) created at:
  github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger.(*Stream).Orchestrate()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/vendor/github.com/dgraph-io/badger/stream.go:333 +0x245
  github.com/dgraph-io/dgraph/worker.export()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:594 +0x11f6
  github.com/dgraph-io/dgraph/worker.handleExportOverNetwork()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:631 +0x4dc
  github.com/dgraph-io/dgraph/worker.ExportOverNetwork.func1()
      /home/dmai/go/src/github.com/dgraph-io/dgraph/worker/export.go:677 +0x197
==================
I0719 01:01:42.381838       1 log.go:34] Export Time elapsed: 01s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:43.381808       1 log.go:34] Export Time elapsed: 02s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:44.381766       1 log.go:34] Export Time elapsed: 03s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:45.381800       1 log.go:34] Export Time elapsed: 04s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:46.381770       1 log.go:34] Export Time elapsed: 05s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:47.381808       1 log.go:34] Export Time elapsed: 06s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:48.381783       1 log.go:34] Export Time elapsed: 07s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:49.381728       1 log.go:34] Export Time elapsed: 08s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:50.381819       1 log.go:34] Export Time elapsed: 09s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:01:51.381848       1 log.go:34] Export Time elapsed: 10s, bytes sent: 0 B, speed: 0 B/sec
I0719 01:02:05.343297       1 log.go:34] Export Created batch of size: 4.3 MB in 13.399968928s.
I0719 01:02:05.343475       1 log.go:34] Export Time elapsed: 23s, bytes sent: 4.3 MB, speed: 186 kB/sec
I0719 01:02:24.964114       1 draft.go:664] [0x1] Set Raft progress to index: 1086693.
I0719 01:03:20.912389       1 log.go:34] Export Created batch of size: 22 MB in 1m15.252888815s.
I0719 01:03:20.912569       1 log.go:34] Export Time elapsed: 01m39s, bytes sent: 26 MB, speed: 262 kB/sec
I0719 01:09:16.307823       1 log.go:34] Export Created batch of size: 119 MB in 5m53.527595628s.
I0719 01:15:02.988192       1 log.go:34] Export Created batch of size: 109 MB in 5m44.933663625s.
I0719 01:15:02.988382       1 log.go:34] Export Time elapsed: 13m21s, bytes sent: 254 MB, speed: 317 kB/sec
I0719 01:15:02.988430       1 log.go:34] Export Sent 3515521 keys
I0719 01:15:03.008241       1 export.go:606] Export DONE for group 1 at timestamp 1190001.
I0719 01:17:11.849978       1 export.go:689] Export at readTs 1190001 DONE

@gitlw gitlw mentioned this issue Jul 19, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
kind/bug Something is broken.
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix race conditions in bulk loader and export dgraph-io/dgraph
1 participant
@danielmai