dgraph alpha painc with badger assert failed error #1369
Comments
|
Hey @QthCN, thanks for raising this issue. I'm aware of the bug and I'm working on trying to reproduce it on my end. How much data were you inserting? |
jarifibrahim
added
the
area/crash
|
@jarifibrahim thanks for the response. I'm using dgraph for program analysis. I encounter this panic problem when I analysis openstack nova project's source code. The number of dgraph's node is the sum of nova's directory number + nova's file number + nova's all file's token. The number of dgraph's edge is the sum of all nova's tokens' relationship. For example, in the following program: There are 9 node in dgraph:
and there are at least 3 edge in dgraph:
The dataset(dgraph disk space usage) of this project won't be very large, littler than 1GB maybe. But the add edge action(set symbol's relationship) will be execute one by one at very high speed. And the error happend when my analysis program executing these add edge action. |
jarifibrahim
added
kind/bug
|
@QthCN Can you confirm the on-disk size of badger directory? |
|
Hey @jarifibrahim , dgraph never finish my request...so I don't know th disk size usage exactly. I run my program again, and dgraph panic again. Before the running, filesystem disk usage: after dgraph panic, filesystem disk usage: I guess the p directory, w directory and zw directory are related to the dgraph(and badger), so the disk usage is around 1.5 GB. Here is the log for this running: |
|
@QthCN Can you share your program with me with instructions on how to run it? Since I can't reproduce it I can't figure out what's going wrong. You can send me an email (Ibrahim[at]dgraph.io) if you're not comfortable sharing the code here. |
|
@jarifibrahim OK, I'll try to remove unreleated code and give you the code to reproduce the problem. Thank you. |
|
This is fixed in ristretto via dgraph-io/ristretto#167 and ristretto was updated in badger via #1391 . @QthCN we'll update badger in dgraph soon and that would fix this crash. |
What version of Go are you using (
go version)?What operating system are you using?
I'm running a program using dgo on a mac, and running dgraph in a virtual box vm. vm operation system info:
What version of Badger are you using?
I'm runnig dgraph as the guide/linux said. From the output I guess the version of Badger is :
Does this issue reproduce with the latest master?
I don't know. I'm using the dgraph binary download page, and I download it yesterday.
Steps to Reproduce the issue
Write a lot of add edge request to dgraph, and dgraph panic with following error:
What Badger options were set?
I just running dgraph with following commands:
What did you do?
I'm running a program using dgo on a mac, and running dgraph in a virtual box vm. The program I'm working on will write a lot of add edge request to dgraph, and I found the dgraph panic sometime with a error stack about badger.
What did you expect to see?
dgraph running without panic.
What did you see instead?
dgraph alphaa log:
thuanqin@devstack:~$ /usr/local/bin/dgraph alpha --lru_mb 4096 [Decoder]: Using assembly version of decoder [Sentry] 2020/06/15 15:51:04 Integration installed: ContextifyFrames [Sentry] 2020/06/15 15:51:04 Integration installed: Environment [Sentry] 2020/06/15 15:51:04 Integration installed: Modules [Sentry] 2020/06/15 15:51:04 Integration installed: IgnoreErrors [Decoder]: Using assembly version of decoder [Sentry] 2020/06/15 15:51:04 Integration installed: ContextifyFrames [Sentry] 2020/06/15 15:51:04 Integration installed: Environment [Sentry] 2020/06/15 15:51:04 Integration installed: Modules [Sentry] 2020/06/15 15:51:04 Integration installed: IgnoreErrors I0615 15:51:05.192922 1756 init.go:99] Dgraph version : v20.03.3 Dgraph SHA-256 : 08424035910be6b6720570427948bab8352a0b5a6d59a0d20c3ec5ed29533121 Commit SHA-1 : fa3c19120 Commit timestamp : 2020-06-02 16:47:25 -0700 Branch : HEAD Go version : go1.14.1 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-2020 Dgraph Labs, Inc. I0615 15:51:05.193388 1756 run.go:608] x.Config: {PortOffset:0 QueryEdgeLimit:1000000 NormalizeNodeLimit:10000} I0615 15:51:05.193655 1756 run.go:609] x.WorkerConfig: {ExportPath:export NumPendingProposals:256 Tracing:0.01 MyAddr: ZeroAddr:[localhost:5080] RaftId:0 WhiteListedIPRanges:[] MaxRetries:-1 StrictMutations:false AclEnabled:false AbortOlderThan:5m0s SnapshotAfter:10000 ProposedGroupId:0 StartTime:2020-06-15 15:51:04.71701086 +0800 CST m=+0.015543543 LudicrousMode:false BadgerKeyFile:} I0615 15:51:05.193812 1756 run.go:610] worker.Config: {PostingDir:p BadgerTables:mmap BadgerVlog:mmap BadgerKeyFile: BadgerCompressionLevel:3 WALDir:w MutationsMode:0 AuthToken: AllottedMemory:4096 HmacSecret:**** AccessJwtTtl:0s RefreshJwtTtl:0s AclRefreshInterval:0s} I0615 15:51:05.193975 1756 server_state.go:75] Setting Badger Compression Level: 3 I0615 15:51:05.194136 1756 server_state.go:84] Setting Badger table load option: mmap I0615 15:51:05.194248 1756 server_state.go:96] Setting Badger value log load option: mmap I0615 15:51:05.194301 1756 server_state.go:141] Opening write-ahead log BadgerDB with options: {Dir:w ValueDir:w SyncWrites:false TableLoadingMode:1 ValueLogLoadingMode:2 NumVersionsToKeep:1 ReadOnly:false Truncate:true Logger:0x28325d0 Compression:2 InMemory:false MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1048576 NumMemtables:5 BlockSize:4096 BloomFalsePositive:0.01 KeepL0InMemory:true MaxCacheSize:10485760 MaxBfCacheSize:0 LoadBloomsOnOpen:false NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:10000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 ZSTDCompressionLevel:3 VerifyValueChecksum:false EncryptionKey:[] EncryptionKeyRotationDuration:240h0m0s BypassLockGuard:false ChecksumVerificationMode:0 KeepBlockIndicesInCache:false KeepBlocksInCache:false managedTxns:false maxBatchCount:0 maxBatchSize:0} I0615 15:51:05.343189 1756 log.go:34] All 8 tables opened in 143ms I0615 15:51:05.348964 1756 log.go:34] Replaying file id: 22 at offset: 53995355 I0615 15:51:05.349127 1756 log.go:34] Replay took: 7.584µs I0615 15:51:05.349306 1756 server_state.go:75] Setting Badger Compression Level: 3 I0615 15:51:05.349316 1756 server_state.go:84] Setting Badger table load option: mmap I0615 15:51:05.349319 1756 server_state.go:96] Setting Badger value log load option: mmap I0615 15:51:05.349325 1756 server_state.go:164] Opening postings BadgerDB with options: {Dir:p ValueDir:p SyncWrites:false TableLoadingMode:2 ValueLogLoadingMode:2 NumVersionsToKeep:2147483647 ReadOnly:false Truncate:true Logger:0x28325d0 Compression:2 InMemory:false MaxTableSize:67108864 LevelSizeMultiplier:10 MaxLevels:7 ValueThreshold:1024 NumMemtables:5 BlockSize:4096 BloomFalsePositive:0.01 KeepL0InMemory:true MaxCacheSize:1073741824 MaxBfCacheSize:0 LoadBloomsOnOpen:false NumLevelZeroTables:5 NumLevelZeroTablesStall:10 LevelOneSize:268435456 ValueLogFileSize:1073741823 ValueLogMaxEntries:1000000 NumCompactors:2 CompactL0OnClose:true LogRotatesToFlush:2 ZSTDCompressionLevel:3 VerifyValueChecksum:false EncryptionKey:[] EncryptionKeyRotationDuration:240h0m0s BypassLockGuard:false ChecksumVerificationMode:0 KeepBlockIndicesInCache:true KeepBlocksInCache:true managedTxns:false maxBatchCount:0 maxBatchSize:0} I0615 15:51:05.450251 1756 log.go:34] All 5 tables opened in 79ms I0615 15:51:05.466089 1756 log.go:34] Replaying file id: 5 at offset: 95043896 I0615 15:51:05.466156 1756 log.go:34] Replay took: 3.67µs I0615 15:51:05.467551 1756 run.go:480] Bringing up GraphQL HTTP API at 0.0.0.0:8080/graphql I0615 15:51:05.467569 1756 run.go:481] Bringing up GraphQL HTTP admin API at 0.0.0.0:8080/admin I0615 15:51:05.467588 1756 run.go:512] gRPC server started. Listening on port 9080 I0615 15:51:05.467595 1756 run.go:513] HTTP server started. Listening on port 8080 I0615 15:51:05.467673 1756 groups.go:107] Current Raft Id: 0x1 I0615 15:51:05.467723 1756 worker.go:96] Worker listening at address: [::]:7080 I0615 15:51:05.568676 1756 pool.go:160] CONNECTING to localhost:5080 I0615 15:51:05.580675 1756 groups.go:135] Connected to group zero. Assigned group: 0 I0615 15:51:05.580693 1756 groups.go:137] Raft Id after connection to Zero: 0x1 I0615 15:51:05.580832 1756 pool.go:160] CONNECTING to localhost:7080 W0615 15:51:05.582362 1756 pool.go:254] Connection lost with localhost:7080. Error: rpc error: code = Unknown desc = No node has been set up yet I0615 15:51:05.583120 1756 draft.go:200] Node ID: 0x1 with GroupID: 1 I0615 15:51:05.583924 1756 node.go:148] Setting raft.Config to: &{ID:1 peers:[] learners:[] ElectionTick:20 HeartbeatTick:1 Storage:0xc02b373940 Applied:67560 MaxSizePerMsg:262144 MaxCommittedSizePerReady:67108864 MaxUncommittedEntriesSize:0 MaxInflightMsgs:256 CheckQuorum:false PreVote:true ReadOnlyOption:0 Logger:0x28325d0 DisableProposalForwarding:false} I0615 15:51:05.596679 1756 node.go:306] Found Snapshot.Metadata: {ConfState:{Nodes:[1] Learners:[] XXX_unrecognized:[]} Index:67560 Term:11 XXX_unrecognized:[]} I0615 15:51:05.597173 1756 node.go:317] Found hardstate: {Term:12 Vote:1 Commit:73707 XXX_unrecognized:[]} I0615 15:51:05.837612 1756 node.go:326] Group 1 found 6147 entries I0615 15:51:05.837831 1756 draft.go:1544] Restarting node for group: 1 I0615 15:51:05.838403 1756 node.go:185] Setting conf state to nodes:1 I0615 15:51:05.839669 1756 log.go:34] 1 became follower at term 12 I0615 15:51:05.840566 1756 log.go:34] newRaft 1 [peers: [1], term: 12, commit: 73707, applied: 67560, lastindex: 73707, lastterm: 12] I0615 15:51:05.840798 1756 draft.go:147] Operation started with id: opRollup I0615 15:51:05.841406 1756 groups.go:155] Server is ready I0615 15:51:05.841579 1756 groups.go:782] Got address of a Zero leader: localhost:5080 I0615 15:51:05.841773 1756 groups.go:796] Starting a new membership stream receive from localhost:5080. I0615 15:51:05.842676 1756 draft.go:962] Found Raft progress: 73706 I0615 15:51:05.843135 1756 groups.go:813] Received first state update from Zero: counter:36348 groups: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > tablets: > snapshot_ts:96569 checksum:2530653943050504975 > > zeros: > maxLeaseId:19084664 maxTxnTs:110000 maxRaftId:1 cid:"caaf6a63-71a2-4988-8d46-53ddd0221caf" license: I0615 15:51:08.643567 1756 log.go:34] 1 is starting a new election at term 12 I0615 15:51:08.643590 1756 log.go:34] 1 became pre-candidate at term 12 I0615 15:51:08.643593 1756 log.go:34] 1 received MsgPreVoteResp from 1 at term 12 I0615 15:51:08.643903 1756 log.go:34] 1 became candidate at term 13 I0615 15:51:08.643911 1756 log.go:34] 1 received MsgVoteResp from 1 at term 13 I0615 15:51:08.644434 1756 log.go:34] 1 became leader at term 13 I0615 15:51:08.644737 1756 log.go:34] raft.node: 1 elected leader 1 at term 13 I0615 15:51:08.842495 1756 groups.go:864] Leader idx=0x1 of group=1 is connecting to Zero for txn updates I0615 15:51:08.842522 1756 groups.go:873] Got Zero leader: localhost:5080 I0615 15:51:10.511217 1756 admin.go:583] No GraphQL schema in Dgraph; serving empty GraphQL API I0615 15:54:21.586963 1756 admin.go:356] Updating GraphQL schema from subscription. E0615 15:54:21.587025 1756 admin.go:386] Error processing GraphQL schema: input: No schema specified. I0615 16:03:06.827033 1756 draft.go:557] Creating snapshot at index: 77921. ReadTs: 114162. I0615 16:04:10.593892 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:04:10.594106 1756 log.go:34] Running for level: 0 I0615 16:04:17.985405 1756 log.go:34] LOG Compact 0->1, del 10 tables, add 8 tables, took 7.391119401s I0615 16:04:17.985440 1756 log.go:34] Compaction for level: 0 DONE I0615 16:05:27.162144 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:05:27.162297 1756 log.go:34] Running for level: 0 I0615 16:05:38.546392 1756 log.go:34] LOG Compact 0->1, del 13 tables, add 11 tables, took 11.38405116s I0615 16:05:38.546545 1756 log.go:34] Compaction for level: 0 DONE I0615 16:06:44.164347 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:06:44.164388 1756 log.go:34] Running for level: 0 I0615 16:06:58.176188 1756 log.go:34] LOG Compact 0->1, del 16 tables, add 14 tables, took 14.011775634s I0615 16:06:58.176359 1756 log.go:34] Compaction for level: 0 DONE I0615 16:09:37.593389 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:09:37.593536 1756 log.go:34] Running for level: 0 I0615 16:09:53.465275 1756 log.go:34] LOG Compact 0->1, del 19 tables, add 16 tables, took 15.87136244s I0615 16:09:53.465511 1756 log.go:34] Compaction for level: 0 DONE I0615 16:10:48.896228 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:10:48.896288 1756 log.go:34] Running for level: 0 I0615 16:10:50.470472 1756 log.go:34] LOG Compact 0->1, del 6 tables, add 4 tables, took 1.574168438s I0615 16:10:50.470501 1756 log.go:34] Compaction for level: 0 DONE I0615 16:10:56.162170 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:10:56.162235 1756 log.go:34] Running for level: 0 I0615 16:11:14.290413 1756 draft.go:557] Creating snapshot at index: 88110. ReadTs: 124279. I0615 16:11:20.052687 1756 log.go:34] LOG Compact 0->1, del 21 tables, add 19 tables, took 23.89041028s I0615 16:11:20.053233 1756 log.go:34] Compaction for level: 0 DONE I0615 16:11:20.053270 1756 log.go:34] Got compaction priority: {level:1 score:1.0411030948162079 dropPrefix:[]} I0615 16:11:20.053479 1756 log.go:34] Running for level: 1 I0615 16:11:21.097878 1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.044162852s I0615 16:11:21.097923 1756 log.go:34] Compaction for level: 1 DONE I0615 16:12:26.594967 1756 log.go:34] Got compaction priority: {level:0 score:1 dropPrefix:[]} I0615 16:12:26.595030 1756 log.go:34] Running for level: 0 I0615 16:12:49.472572 1756 log.go:34] LOG Compact 0->1, del 23 tables, add 21 tables, took 22.877516219s I0615 16:12:49.472629 1756 log.go:34] Compaction for level: 0 DONE I0615 16:12:49.472664 1756 log.go:34] Got compaction priority: {level:1 score:1.1536962911486626 dropPrefix:[]} I0615 16:12:49.472707 1756 log.go:34] Running for level: 1 I0615 16:12:50.162227 1756 log.go:34] Got compaction priority: {level:1 score:1.1092977710068226 dropPrefix:[]} I0615 16:12:50.162288 1756 log.go:34] Running for level: 1 I0615 16:12:50.499999 1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.027274736s I0615 16:12:50.500076 1756 log.go:34] Compaction for level: 1 DONE I0615 16:12:50.500095 1756 log.go:34] Got compaction priority: {level:1 score:1.0620409436523914 dropPrefix:[]} I0615 16:12:50.500150 1756 log.go:34] Running for level: 1 I0615 16:12:51.397956 1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.235622196s I0615 16:12:51.398203 1756 log.go:34] Compaction for level: 1 DONE I0615 16:12:51.734052 1756 log.go:34] LOG Compact 1->2, del 1 tables, add 1 tables, took 1.233882982s I0615 16:12:51.734101 1756 log.go:34] Compaction for level: 1 DONE 2020/06/15 16:17:04 Assert failed github.com/dgraph-io/badger/v2/y.AssertTrue /go/pkg/mod/github.com/dgraph-io/badger/v2@v2.0.1-rc1.0.20200528205344-e7b6e76f96e8/y/error.go:55 github.com/dgraph-io/badger/v2/table.(*block).decrRef /go/pkg/mod/github.com/dgraph-io/badger/v2@v2.0.1-rc1.0.20200528205344-e7b6e76f96e8/table/table.go:244 github.com/dgraph-io/badger/v2/table.BlockEvictHandler /go/pkg/mod/github.com/dgraph-io/badger/v2@v2.0.1-rc1.0.20200528205344-e7b6e76f96e8/table/table.go:190 github.com/dgraph-io/badger/v2.Open.func4 /go/pkg/mod/github.com/dgraph-io/badger/v2@v2.0.1-rc1.0.20200528205344-e7b6e76f96e8/db.go:303 github.com/dgraph-io/ristretto.(*Cache).processItems /go/pkg/mod/github.com/dgraph-io/ristretto@v0.0.2-0.20200115201040-8f368f2f2ab3/cache.go:285 runtime.goexit /usr/local/go/src/runtime/asm_amd64.s:1373 thuanqin@devstack:~$The text was updated successfully, but these errors were encountered: