Badger performance and memory usage recommendations


(Tom) #1

Hello,

I’m looking for recommendations related to improving data ingestion performance as well as reduction in memory consumption. Any advice or insight would be greatly appreciated.

Use case:
Ingesting nearly 2 billion JSON formatted records stored in a gzip file. Each data set would be ingested once into a dedicated database and another application would open the database in read only mode for serving data to client software.

Our goals are fast ingestion without crashing due to running out of memory with the least amount of wasted space when done.

Testing system
Ubuntu 18.04 LTS VMware VM
16 vCPU, 64 GB vRAM
Single disk SSD - Samsung EVO 860 - 1 TB
GOMAXPROCS=128

Test data
Single gzipped file containing 1,838,808,242 records
20 GB gzipped, ~ 187 GB uncompressed
Each line is a JSON record with 4 fields
We are creating the record key extracting 3 fields, concat’ing them with a prefix for the record type. Keys are almost always less than 128 bytes. In fact, in one test only 55,000 exceeded this length.
The value is always byte(“0”)

Current Database options

	opts := badger.DefaultOptions
	opts.Dir = dbDir
	opts.ValueDir = valDir
	opts.SyncWrites = false
	opts.CompactL0OnClose = true
	opts.ValueLogLoadingMode = options.FileIO
	opts.ValueLogMaxEntries = 10000000

First issue - Memory consumption
When we first started using ‘db.NewWriteBatch()’ we kept running into memory issues around 975,000,000 records or so.

2019/04/06 08:18:33 Current source record: 974000000
badger 2019/04/06 08:18:33 DEBUG: LOG Compact. Added 1316656 keys. Skipped 0 keys. Iteration took: 1.415085829s
badger 2019/04/06 08:18:34 DEBUG: LOG Compact. Added 1466900 keys. Skipped 0 keys. Iteration took: 1.329849604s
badger 2019/04/06 08:18:35 DEBUG: LOG Compact. Added 1336903 keys. Skipped 0 keys. Iteration took: 1.52772797s
badger 2019/04/06 08:18:35 DEBUG: LOG Compact. Added 1468661 keys. Skipped 0 keys. Iteration took: 1.45960301s
badger 2019/04/06 08:18:37 DEBUG: LOG Compact. Added 1345710 keys. Skipped 0 keys. Iteration took: 2.016639007s
badger 2019/04/06 08:18:37 DEBUG: LOG Compact. Added 1467377 keys. Skipped 0 keys. Iteration took: 1.752152474s
badger 2019/04/06 08:18:39 DEBUG: LOG Compact. Added 1268841 keys. Skipped 0 keys. Iteration took: 1.983111721s
badger 2019/04/06 08:18:39 DEBUG: LOG Compact. Added 1388478 keys. Skipped 0 keys. Iteration took: 1.764262812s
badger 2019/04/06 08:18:42 DEBUG: LOG Compact. Added 1325441 keys. Skipped 0 keys. Iteration took: 3.410780942s
badger 2019/04/06 08:18:42 DEBUG: LOG Compact. Added 1315629 keys. Skipped 0 keys. Iteration took: 3.58924915s
2019/04/06 08:18:43 Current source record: 975000000
badger 2019/04/06 08:18:47 DEBUG: LOG Compact. Added 1045074 keys. Skipped 0 keys. Iteration took: 4.432719609s
badger 2019/04/06 08:18:47 DEBUG: LOG Compact. Added 1284096 keys. Skipped 0 keys. Iteration took: 5.035785182s
fatal error: runtime: cannot allocate memory

runtime stack:
runtime.throw(0x90aaa0, 0x1f)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.persistentalloc1(0x4000, 0x0, 0xcf82d8, 0x7f9fc7a2dd48)
	/usr/local/go/src/runtime/malloc.go:1235 +0x2b7
runtime.persistentalloc.func1()
	/usr/local/go/src/runtime/malloc.go:1189 +0x45
runtime.persistentalloc(0x4000, 0x0, 0xcf82d8, 0x7f9edeb58f40)
	/usr/local/go/src/runtime/malloc.go:1188 +0x82
runtime.(*fixalloc).alloc(0xce2320, 0x1)
	/usr/local/go/src/runtime/mfixalloc.go:80 +0xf5
runtime.(*mheap).allocSpanLocked(0xcdfe20, 0x1, 0xcf82a8, 0x7f9edeb586d0)
	/usr/local/go/src/runtime/mheap.go:1175 +0x191
runtime.(*mheap).alloc_m(0xcdfe20, 0x1, 0x450005, 0x7f9edeb586d0)
	/usr/local/go/src/runtime/mheap.go:977 +0xc2
runtime.(*mheap).alloc.func1()
	/usr/local/go/src/runtime/mheap.go:1048 +0x4c

We were able to work around this by using .Flush() and creating a new db.NewWriteBatch every 10 million records or so. I’m sure the limit is much higher but this seemed to work without much of a throughput issue.

Is this expected? We though that the batching process would handle this automatically.

Second Issue - Disk consumption
The import process and cleanup takes around 5 hours. The result is 242 GBs of data in 1,620 files. The database takes about 6 minutes to open.

badger --info shows the following:

[Summary]
Level 0 size:          0 B
Level 1 size:          0 B
Level 2 size:          0 B
Level 3 size:          0 B
Level 4 size:       100 GB
Total index size:   100 GB
Value log size:     160 GB

The value log file seems very large to me given that each value for the records above is just ‘0’. Is this to be expected? Possibly related, I’ve set opts.ValueLogMaxEntries = 10000000 with the goal of reducing the number of value files given the small size of the data stored there.

I’ve seen smaller results in the past but it seems to be inconsistent. For example the import process batches imports, performs a flatten, and then runs GC until it returns non-nil. I then close the database and reopen it, rerun flatten and GC and find that there is almost always more work for flatten to do and often work work GC to do.

After typing this up I reran a flatten / GC again (3rd time for both) and the database went from
242 GB -> 218 GB
1,620 files -> 1,558

Here is the updated badger --info

[Summary]
Level 0 size:          0 B
Level 1 size:          0 B
Level 2 size:          0 B
Level 3 size:          0 B
Level 4 size:       100 GB
Total index size:   100 GB
Value log size:     133 GB

I ran it again and flatten / GC made no changes. I’ve just kicked it off again an GC is performing some work. I’ll update the post with the results.

Is this expected?

Third Issue - speed of ingestion
We’re currently able to ingest about 10 million records a minute. This varies slightly depending on compaction. We’re not running GC during the ingestion process. We’re using 2 compactors but have tried with 4. I feel like we’re outrunning Level 0/ Level 1 tables but I haven’t been able to speed this up via tuning opts.LevelOneSize and similar. Are there any recommendations for improving the ingestion? Would larger database sizes reduce the performance hit due to compaction or would it just be worse when it finally hits.

Thanks in advance

  • Tom

(Tom) #2

Here are a few log snippets from my application during ingestion

2019/04/07 09:51:34 Current source record:   10000000 - Errors: 0
2019/04/07 09:52:32 Current source record:   20000000 - Errors: 0
2019/04/07 09:53:37 Current source record:   30000000 - Errors: 0


2019/04/08 09:01:09 Current source record: 1490000000 - Errors: 0
2019/04/08 09:02:07 Current source record: 1500000000 - Errors: 0
2019/04/08 09:03:06 Current source record: 1510000000 - Errors: 0
2019/04/08 09:06:02 Current source record: 1520000000 - Errors: 0


2019/04/08 09:52:19 Current source record: 1810000000 - Errors: 0
2019/04/08 09:53:28 Current source record: 1820000000 - Errors: 0
2019/04/08 09:54:35 Current source record: 1830000000 - Errors: 0


2019/04/08 09:55:33 Final source record: 1838808242 - Errors: 0
2019/04/08 09:55:33 Performing flush
2019/04/08 09:55:34 Flush complete
2019/04/08 09:55:34 Time taken to load entries: 4h22m39.58846551s
2019/04/08 09:55:34 Starting database flatten process..
2019/04/08 10:17:54 Time taken to flatten: 22m19.85062305s
2019/04/08 10:17:54 Performing database garbage collection
2019/04/08 10:18:04 Value log GC attempt didn't result in any cleanup
2019/04/08 10:18:04 Database garbage collection completed
2019/04/08 10:18:04 Time taken to garbage collect: 10.002131779s
2019/04/08 10:18:04 File import complete, shutting down database, this can take a while depending on database state.


2019/04/08 10:18:06 Opening database to perform maintenance

badger 2019/04/08 10:23:33 INFO: All 1457 tables opened in 5m27.273s
badger 2019/04/08 10:23:33 DEBUG: Value Log Discard stats: map[]
badger 2019/04/08 10:23:33 INFO: Replaying file id: 188 at offset: 649131511
badger 2019/04/08 10:23:33 INFO: Replay took: 16.411µs
2019/04/08 10:23:33 Starting database flatten process..
2019/04/08 10:45:20 Time taken to flatten: 21m46.745376668s
2019/04/08 10:45:20 Performing database garbage collection
2019/04/08 10:45:30 Value log GC attempt didn't result in any cleanup
2019/04/08 10:45:30 Database garbage collection completed
2019/04/08 10:45:30 Time taken to garbage collect: 10.002683876s
2019/04/08 10:45:30 Database maintenance complete, shutting down database...


(Manish R Jain) #3

Just filed an issue for BatchWriter:

Level 4 has 100 GB there.

GC calls are not deterministic. They don’t do a full sweep over everything. They only pick a file (per call) which they think have the best chance of resulting some cleanup. There’re some instructions in the README about how often to run GC, etc.

Flatten’s job is just to flatten everything into one level of LSM tree. Once they are there, it doesn’t do any more compactions on top of that.

If the bottleneck is go from L0 -> L1, then increasing the number of compactors won’t improve that. Only one compactor can do L0 -> L1, the way that level works. But, the real question would be to ascertain that that is in fact the case from logs or event logs. It could be that you’re hitting disk write limits…

Can you check how much speed do you get from badger fill? You can set the key-value size corresponding to your data.


(Tom) #4

Thanks for the response.

Thanks for the tip on badger fill. I ran in the VM mentioned above and it crashed with fatal error: runtime: cannot allocate memory. Here are some snippets of the logs:

 ~/go/bin/badger fill -k 128 -v 1 -m 1870 --dir ./test_dir/
Listening for /debug HTTP requests at port: 8080
badger 2019/04/09 06:30:04 INFO: All 0 tables opened in 0s
badger 2019/04/09 06:30:04 INFO: Written keys: 100000
badger 2019/04/09 06:30:05 INFO: Written keys: 200000
badger 2019/04/09 06:30:05 INFO: Written keys: 300000
badger 2019/04/09 06:30:05 INFO: Written keys: 400000
badger 2019/04/09 06:30:05 INFO: Written keys: 500000
badger 2019/04/09 06:30:05 INFO: Written keys: 600000
badger 2019/04/09 06:30:06 DEBUG: Storing value log head: {Fid:0 Len:42 Offset:68108178}
badger 2019/04/09 06:30:06 INFO: Written keys: 700000
badger 2019/04/09 06:30:06 INFO: Written keys: 800000



badger 2019/04/09 06:32:14 INFO: Written keys: 39300000
badger 2019/04/09 06:32:14 DEBUG: LOG Compact. Added 452420 keys. Skipped 0 keys. Iteration took: 376.596396ms
badger 2019/04/09 06:32:14 DEBUG: Discard stats: map[]
badger 2019/04/09 06:32:14 INFO: LOG Compact 1->2, del 6 tables, add 6 tables, took 3.892761801s
badger 2019/04/09 06:32:14 INFO: Compaction for level: 1 DONE
badger 2019/04/09 06:32:14 INFO: Got compaction priority: {level:1 score:1.3857654333114624 dropPrefix:[]}
badger 2019/04/09 06:32:14 INFO: Running for level: 1
badger 2019/04/09 06:32:15 INFO: Written keys: 39400000
badger 2019/04/09 06:32:15 DEBUG: LOG Compact. Added 452428 keys. Skipped 0 keys. Iteration took: 347.817725ms
badger 2019/04/09 06:32:15 DEBUG: LOG Compact. Added 452350 keys. Skipped 0 keys. Iteration took: 337.985284ms
badger 2019/04/09 06:32:15 INFO: Written keys: 39500000
badger 2019/04/09 06:32:15 DEBUG: LOG Compact. Added 452427 keys. Skipped 0 keys. Iteration took: 349.230227ms
badger 2019/04/09 06:32:15 INFO: Written keys: 39600000
badger 2019/04/09 06:32:15 DEBUG: LOG Compact. Added 452425 keys. Skipped 0 keys. Iteration took: 342.149219ms
badger 2019/04/09 06:32:15 DEBUG: LOG Compact. Added 452418 keys. Skipped 0 keys. Iteration took: 346.880402ms
badger 2019/04/09 06:32:15 INFO: Written keys: 39700000
badger 2019/04/09 06:32:16 DEBUG: LOG Compact. Added 452425 keys. Skipped 0 keys. Iteration took: 815.765027ms
badger 2019/04/09 06:32:16 DEBUG: LOG Compact. Added 450327 keys. Skipped 0 keys. Iteration took: 920.722591ms
badger 2019/04/09 06:32:16 INFO: Written keys: 39800000
badger 2019/04/09 06:32:16 DEBUG: LOG Compact. Added 438941 keys. Skipped 0 keys. Iteration took: 483.397659ms
badger 2019/04/09 06:32:17 INFO: Written keys: 39900000
badger 2019/04/09 06:32:17 INFO: Written keys: 40000000
badger 2019/04/09 06:32:17 DEBUG: Discard stats: map[]
badger 2019/04/09 06:32:17 INFO: LOG Compact 1->2, del 4 tables, add 4 tables, took 2.79223449s
badger 2019/04/09 06:32:17 INFO: Compaction for level: 1 DONE
badger 2019/04/09 06:32:17 INFO: Got compaction priority: {level:1 score:1.1305567659437656 dropPrefix:[]}
badger 2019/04/09 06:32:17 INFO: Running for level: 1



badger 2019/04/09 06:41:25 INFO: LOG Compact 2->3, del 4 tables, add 4 tables, took 4.10984117s
badger 2019/04/09 06:41:25 INFO: Compaction for level: 2 DONE
badger 2019/04/09 06:41:25 DEBUG: LOG Compact. Added 451468 keys. Skipped 0 keys. Iteration took: 701.442203ms
badger 2019/04/09 06:41:25 INFO: Written keys: 195500000
badger 2019/04/09 06:41:26 DEBUG: Storing value log head: {Fid:74 Len:45 Offset:136216431}
badger 2019/04/09 06:41:26 INFO: Written keys: 195600000
badger 2019/04/09 06:41:26 DEBUG: LOG Compact. Added 452282 keys. Skipped 0 keys. Iteration took: 578.094859ms
badger 2019/04/09 06:41:26 INFO: Written keys: 195700000
badger 2019/04/09 06:41:26 INFO: Written keys: 195800000
badger 2019/04/09 06:41:27 DEBUG: LOG Compact. Added 450930 keys. Skipped 0 keys. Iteration took: 679.329394ms
badger 2019/04/09 06:41:27 INFO: Written keys: 195900000
badger 2019/04/09 06:41:27 DEBUG: Storing value log head: {Fid:75 Len:45 Offset:34054074}
badger 2019/04/09 06:41:27 INFO: Written keys: 196000000
badger 2019/04/09 06:41:27 DEBUG: LOG Compact. Added 450334 keys. Skipped 0 keys. Iteration took: 551.186796ms
badger 2019/04/09 06:41:27 INFO: Written keys: 196100000
badger 2019/04/09 06:41:28 INFO: Written keys: 196200000
badger 2019/04/09 06:41:28 DEBUG: LOG Compact. Added 450840 keys. Skipped 0 keys. Iteration took: 777.465481ms
badger 2019/04/09 06:41:28 INFO: Written keys: 196300000
badger 2019/04/09 06:41:28 DEBUG: Storing value log head: {Fid:75 Len:45 Offset:102162312}
badger 2019/04/09 06:41:28 DEBUG: LOG Compact. Added 320117 keys. Skipped 0 keys. Iteration took: 506.657232ms
badger 2019/04/09 06:41:29 INFO: Written keys: 196400000
badger 2019/04/09 06:41:29 INFO: Written keys: 196500000
badger 2019/04/09 06:41:29 DEBUG: Discard stats: map[]
badger 2019/04/09 06:41:29 INFO: LOG Compact 0->1, del 8 tables, add 8 tables, took 5.855125085s
badger 2019/04/09 06:41:29 INFO: Compaction for level: 0 DONE
badger 2019/04/09 06:41:29 INFO: Got compaction priority: {level:1 score:1.9661771543323994 dropPrefix:[]}
badger 2019/04/09 06:41:29 INFO: Running for level: 1
badger 2019/04/09 06:41:29 INFO: Written keys: 196600000
badger 2019/04/09 06:41:29 DEBUG: Storing value log head: {Fid:75 Len:45 Offset:170270550}
badger 2019/04/09 06:41:29 DEBUG: LOG Compact. Added 452386 keys. Skipped 0 keys. Iteration took: 410.431503ms
badger 2019/04/09 06:41:29 INFO: Written keys: 196700000
badger 2019/04/09 06:41:29 INFO: Got compaction priority: {level:1 score:1.7109682112932205 dropPrefix:[]}
badger 2019/04/09 06:41:29 INFO: Running for level: 1
badger 2019/04/09 06:41:30 INFO: Written keys: 196800000
badger 2019/04/09 06:41:30 INFO: Written keys: 196900000
badger 2019/04/09 06:41:30 DEBUG: LOG Compact. Added 452605 keys. Skipped 0 keys. Iteration took: 681.923915ms
badger 2019/04/09 06:41:30 DEBUG: LOG Compact. Added 451489 keys. Skipped 0 keys. Iteration took: 655.931998ms
badger 2019/04/09 06:41:30 INFO: Written keys: 197000000
badger 2019/04/09 06:41:30 INFO: Written keys: 197100000
badger 2019/04/09 06:41:31 DEBUG: Storing value log head: {Fid:76 Len:45 Offset:68108193}
badger 2019/04/09 06:41:31 INFO: Written keys: 197200000
badger 2019/04/09 06:41:31 DEBUG: LOG Compact. Added 452553 keys. Skipped 0 keys. Iteration took: 1.121580149s
badger 2019/04/09 06:41:31 DEBUG: LOG Compact. Added 452588 keys. Skipped 0 keys. Iteration took: 1.132710899s
badger 2019/04/09 06:41:31 INFO: Written keys: 197300000
badger 2019/04/09 06:41:32 INFO: Written keys: 197400000
badger 2019/04/09 06:41:32 INFO: Written keys: 197500000
badger 2019/04/09 06:41:32 INFO: Written keys: 197600000
badger 2019/04/09 06:41:32 DEBUG: LOG Compact. Added 452801 keys. Skipped 0 keys. Iteration took: 1.179788511s
badger 2019/04/09 06:41:32 DEBUG: LOG Compact. Added 452701 keys. Skipped 0 keys. Iteration took: 1.214919477s
fatal error: runtime: cannot allocate memory

runtime stack:
runtime.throw(0x96175d, 0x1f)
	/usr/local/go/src/runtime/panic.go:617 +0x72
runtime.persistentalloc1(0x4000, 0x0, 0xd94638, 0x7fc480446910)
	/usr/local/go/src/runtime/malloc.go:1235 +0x2b7
runtime.persistentalloc.func1()
	/usr/local/go/src/runtime/malloc.go:1189 +0x45
runtime.persistentalloc(0x4000, 0x0, 0xd94638, 0x7fc47f1ccf40)
	/usr/local/go/src/runtime/malloc.go:1188 +0x82
runtime.(*fixalloc).alloc(0xd7e600, 0x1)
	/usr/local/go/src/runtime/mfixalloc.go:80 +0xf5
runtime.(*mheap).allocSpanLocked(0xd7c100, 0x1, 0xd94608, 0x7fc47f1ccd00)
	/usr/local/go/src/runtime/mheap.go:1175 +0x191
runtime.(*mheap).alloc_m(0xd7c100, 0x1, 0x45000c, 0x7fc47f1ccd00)
	/usr/local/go/src/runtime/mheap.go:977 +0xc2
runtime.(*mheap).alloc.func1()
	/usr/local/go/src/runtime/mheap.go:1048 +0x4c
runtime.systemstack(0x0)
	/usr/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1153

goroutine 1 [running]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:311 fp=0xc0001a6918 sp=0xc0001a6910 pc=0x45b450
runtime.(*mheap).alloc(0xd7c100, 0x1, 0x1000c, 0xc423430e00)
	/usr/local/go/src/runtime/mheap.go:1047 +0x8a fp=0xc0001a6968 sp=0xc0001a6918 pc=0x42625a
runtime.(*mcentral).grow(0xd7c780, 0x0)
	/usr/local/go/src/runtime/mcentral.go:256 +0x95 fp=0xc0001a69b0 sp=0xc0001a6968 pc=0x419195
runtime.(*mcentral).cacheSpan(0xd7c780, 0x80)
	/usr/local/go/src/runtime/mcentral.go:106 +0x2ff fp=0xc0001a6a10 sp=0xc0001a69b0 pc=0x418c9f
runtime.(*mcache).refill(0x7fc77e96a8b8, 0xc)
	/usr/local/go/src/runtime/mcache.go:135 +0x86 fp=0xc0001a6a30 sp=0xc0001a6a10 pc=0x418736
runtime.(*mcache).nextFree(0x7fc77e96a8b8, 0xc, 0xc000040070, 0xc000040000, 0xbc0a3c26413bc608)
	/usr/local/go/src/runtime/malloc.go:786 +0x88 fp=0xc0001a6a68 sp=0xc0001a6a30 pc=0x40d058
runtime.mallocgc(0x50, 0x921f00, 0x1, 0xc423430e00)
	/usr/local/go/src/runtime/malloc.go:939 +0x76e fp=0xc0001a6b08 sp=0xc0001a6a68 pc=0x40d96e
runtime.newobject(0x921f00, 0x0)
	/usr/local/go/src/runtime/malloc.go:1068 +0x38 fp=0xc0001a6b38 sp=0xc0001a6b08 pc=0x40dd78
github.com/dgraph-io/badger.(*WriteBatch).Set(...)
	/home/ubuntu/go/src/github.com/dgraph-io/badger/batch.go:92
github.com/dgraph-io/badger/badger/cmd.fill(0xd6ccc0, 0xc00014e300, 0x0, 0x8, 0x0, 0x0)
	/home/ubuntu/go/src/github.com/dgraph-io/badger/badger/cmd/fill.go:82 +0x370 fp=0xc0001a6d58 sp=0xc0001a6b38 pc=0x84c370
github.com/spf13/cobra.(*Command).execute(0xd6ccc0, 0xc00014e280, 0x8, 0x8, 0xd6ccc0, 0xc00014e280)
	/home/ubuntu/go/src/github.com/spf13/cobra/command.go:762 +0x465 fp=0xc0001a6e40 sp=0xc0001a6d58 pc=0x841065
github.com/spf13/cobra.(*Command).ExecuteC(0xd6d640, 0xc0000edf40, 0x432ef3, 0xd3634c)
	/home/ubuntu/go/src/github.com/spf13/cobra/command.go:850 +0x2fc fp=0xc0001a6f18 sp=0xc0001a6e40 pc=0x841b0c
github.com/spf13/cobra.(*Command).Execute(...)
	/home/ubuntu/go/src/github.com/spf13/cobra/command.go:800
github.com/dgraph-io/badger/badger/cmd.Execute()
	/home/ubuntu/go/src/github.com/dgraph-io/badger/badger/cmd/root.go:40 +0x32 fp=0xc0001a6f78 sp=0xc0001a6f18 pc=0x850232
main.main()
	/home/ubuntu/go/src/github.com/dgraph-io/badger/badger/main.go:41 +0x54 fp=0xc0001a6f98 sp=0xc0001a6f78 pc=0x8517b4
runtime.main()
	/usr/local/go/src/runtime/proc.go:200 +0x20c fp=0xc0001a6fe0 sp=0xc0001a6f98 pc=0x43083c
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:1337 +0x1 fp=0xc0001a6fe8 sp=0xc0001a6fe0 pc=0x45d521

goroutine 34 [IO wait, 11 minutes]:
internal/poll.runtime_pollWait(0x7fc77e888ea8, 0x72, 0x0)
	/usr/local/go/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc0001ce098, 0x72, 0x0, 0x0, 0x953673)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*pollDesc).waitRead(...)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc0001ce080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:384 +0x1ba
net.(*netFD).accept(0xc0001ce080, 0x916440, 0x50, 0xc0001ac320)
	/usr/local/go/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc00015a038, 0xc000064a80, 0x7fc77e969460, 0x0)
	/usr/local/go/src/net/tcpsock_posix.go:139 +0x32
net.(*TCPListener).AcceptTCP(0xc00015a038, 0x40dd78, 0x30, 0x916440)
	/usr/local/go/src/net/tcpsock.go:247 +0x48
net/http.tcpKeepAliveListener.Accept(0xc00015a038, 0x916440, 0xc000148660, 0x8c34e0, 0xd63cd0)
	/usr/local/go/src/net/http/server.go:3264 +0x2f
net/http.(*Server).Serve(0xc0001aa000, 0xa0ba60, 0xc00015a038, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:2859 +0x22d
net/http.(*Server).ListenAndServe(0xc0001aa000, 0xc0001aa000, 0xc0001a4fc0)
	/usr/local/go/src/net/http/server.go:2797 +0xe4
net/http.ListenAndServe(...)
	/usr/local/go/src/net/http/server.go:3037
main.main.func1()
	/home/ubuntu/go/src/github.com/dgraph-io/badger/badger/main.go:32 +0x19f
created by main.main
	/home/ubuntu/go/src/github.com/dgraph-io/badger/badger/main.go:29 +0x35

goroutine 35 [select]:
github.com/dgraph-io/badger/y.(*WaterMark).process(0xc0001502c0, 0xc00013ee20)
	/home/ubuntu/go/src/github.com/dgraph-io/badger/y/watermark.go:207 +0x2d1
created by github.com/dgraph-io/badger/y.(*WaterMark).Init
	/home/ubuntu/go/src/github.com/dgraph-io/badger/y/watermark.go:74 +0xc9

goroutine 36 [select]:
github.com/dgraph-io/badger/y.(*WaterMark).process(0xc000150300, 0xc00013ee20)
	/home/ubuntu/go/src/github.com/dgraph-io/badger/y/watermark.go:207 +0x2d1
created by github.com/dgraph-io/badger/y.(*WaterMark).Init
	/home/ubuntu/go/src/github.com/dgraph-io/badger/y/watermark.go:74 +0xc9

goroutine 37 [select]:
github.com/dgraph-io/badger.(*DB).updateSize(0xc000300000, 0xc00013eec0)
	/home/ubuntu/go/src/github.com/dgraph-io/badger/db.go:952 +0x12f
created by github.com/dgraph-io/badger.Open
	/home/ubuntu/go/src/github.com/dgraph-io/badger/db.go:266 +0x810

goroutine 185 [running]:
	goroutine running on other thread; stack unavailable
created by github.com/dgraph-io/badger.(*levelsController).startCompact
	/home/ubuntu/go/src/github.com/dgraph-io/badger/levels.go:329 +0x89

goroutine 186 [running]:
	goroutine running on other thread; stack unavailable
created by github.com/dgraph-io/badger.(*levelsController).startCompact
	/home/ubuntu/go/src/github.com/dgraph-io/badger/levels.go:329 +0x89

goroutine 187 [running]:
	goroutine running on other thread; stack unavailable
created by github.com/dgraph-io/badger.Open
	/home/ubuntu/go/src/github.com/dgraph-io/badger/db.go:279 +0x10cc

goroutine 189 [select]:
github.com/dgraph-io/badger.(*DB).doWrites(0xc000300000, 0xc00000e320)
	/home/ubuntu/go/src/github.com/dgraph-io/badger/db.go:689 +0x2bc
created by github.com/dgraph-io/badger.Open
	/home/ubuntu/go/src/github.com/dgraph-io/badger/db.go:312 +0xd19

The only logs in this timeframe for the system are these entries from /var/log/syslog

Apr  9 06:40:40 userver systemd[1]: Starting Cleanup of Temporary Directories...
Apr  9 06:40:40 userver systemd[1]: Started Cleanup of Temporary Directories.

badger info information from the directory

EXTRA]
[2019-04-09T06:41:30-05:00] 001651.sst    68 MB
[2019-04-09T06:41:30-05:00] 001652.sst    68 MB
[2019-04-09T06:41:30-05:00] 001653.sst    68 MB
[2019-04-09T06:41:31-05:00] 001654.sst    65 MB
[2019-04-09T06:41:31-05:00] 001655.sst    68 MB
[2019-04-09T06:41:31-05:00] 001656.sst    68 MB
[2019-04-09T06:41:32-05:00] 001657.sst      0 B
[2019-04-09T06:41:32-05:00] 001658.sst      0 B
[2019-04-09T06:30:04-05:00] LOCK            5 B

[Summary]
Level 0 size:       388 MB
Level 1 size:       528 MB
Level 2 size:       2.6 GB
Level 3 size:       8.8 GB
Total index size:    12 GB
Value log size:      17 GB

Abnormalities:
9 extra files.
0 missing files.
0 empty files.
0 truncated manifests.

(Tom) #5

I ran the same command on my Mac. It made it further and then was killed. I know it was using something like 51 GB of memory around that time.

 ~/go/bin/badger fill -k 128 -v 1 -m 1870 --dir ./test_dir/
Listening for /debug HTTP requests at port: 8080
badger 2019/04/09 06:50:41 INFO: All 0 tables opened in 0s
badger 2019/04/09 06:50:42 INFO: Written keys: 100000
badger 2019/04/09 06:50:44 INFO: Written keys: 200000
badger 2019/04/09 06:50:45 INFO: Written keys: 300000
badger 2019/04/09 06:50:46 INFO: Written keys: 400000
badger 2019/04/09 06:50:47 INFO: Written keys: 500000
badger 2019/04/09 06:50:47 DEBUG: Storing value log head: {Fid:0 Len:42 Offset:68108178}
badger 2019/04/09 06:50:48 INFO: Written keys: 600000
badger 2019/04/09 06:50:49 INFO: Written keys: 700000
badger 2019/04/09 06:50:51 INFO: Written keys: 800000
badger 2019/04/09 06:50:52 INFO: Written keys: 900000
badger 2019/04/09 06:50:52 DEBUG: Storing value log head: {Fid:0 Len:43 Offset:136216400}
badger 2019/04/09 06:50:53 INFO: Written keys: 1000000
badger 2019/04/09 06:50:54 INFO: Written keys: 1100000
badger 2019/04/09 06:50:55 INFO: Written keys: 1200000
badger 2019/04/09 06:50:56 INFO: Written keys: 1300000
badger 2019/04/09 06:50:57 DEBUG: Storing value log head: {Fid:1 Len:43 Offset:34054070}
badger 2019/04/09 06:50:58 INFO: Written keys: 1400000
badger 2019/04/09 06:50:59 INFO: Written keys: 1500000



badger 2019/04/09 07:19:55 DEBUG: LOG Compact. Added 452675 keys. Skipped 0 keys. Iteration took: 2.168048573s
badger 2019/04/09 07:19:56 DEBUG: Discard stats: map[]
badger 2019/04/09 07:19:56 INFO: LOG Compact 1->2, del 5 tables, add 5 tables, took 17.859557588s
badger 2019/04/09 07:19:56 INFO: Compaction for level: 1 DONE
badger 2019/04/09 07:19:56 INFO: Got compaction priority: {level:1 score:1.7974398918449879 dropPrefix:[]}
badger 2019/04/09 07:19:56 INFO: Running for level: 1
badger 2019/04/09 07:19:56 INFO: Written keys: 83400000
badger 2019/04/09 07:19:57 DEBUG: LOG Compact. Added 452198 keys. Skipped 0 keys. Iteration took: 1.739290167s
badger 2019/04/09 07:19:58 DEBUG: LOG Compact. Added 452312 keys. Skipped 0 keys. Iteration took: 2.180772321s
badger 2019/04/09 07:19:59 INFO: Written keys: 83500000
badger 2019/04/09 07:20:00 DEBUG: LOG Compact. Added 452515 keys. Skipped 0 keys. Iteration took: 3.340432804s
badger 2019/04/09 07:20:01 DEBUG: LOG Compact. Added 452385 keys. Skipped 0 keys. Iteration took: 3.096309048s
badger 2019/04/09 07:20:09 DEBUG: LOG Compact. Added 445978 keys. Skipped 0 keys. Iteration took: 8.396449584s
badger 2019/04/09 07:20:09 INFO: Written keys: 83600000
badger 2019/04/09 07:20:09 DEBUG: LOG Compact. Added 452590 keys. Skipped 0 keys. Iteration took: 8.454777881s
badger 2019/04/09 07:20:11 INFO: Written keys: 83700000
badger 2019/04/09 07:20:12 DEBUG: Discard stats: map[]
badger 2019/04/09 07:20:12 DEBUG: LOG Compact. Added 452635 keys. Skipped 0 keys. Iteration took: 2.635131638s
badger 2019/04/09 07:20:12 INFO: LOG Compact 1->2, del 7 tables, add 7 tables, took 32.185226564s
badger 2019/04/09 07:20:12 INFO: Compaction for level: 1 DONE
badger 2019/04/09 07:20:12 INFO: Got compaction priority: {level:1 score:1.5422310307621956 dropPrefix:[]}
badger 2019/04/09 07:20:12 INFO: Running for level: 1





badger 2019/04/09 09:28:59 DEBUG: LOG Compact. Added 452547 keys. Skipped 0 keys. Iteration took: 20.813043855s
badger 2019/04/09 09:29:02 INFO: Written keys: 157800000
badger 2019/04/09 09:29:04 INFO: Written keys: 157900000
badger 2019/04/09 09:29:09 DEBUG: LOG Compact. Added 452831 keys. Skipped 0 keys. Iteration took: 23.118422131s
badger 2019/04/09 09:29:24 INFO: Written keys: 158000000
badger 2019/04/09 09:29:26 DEBUG: LOG Compact. Added 452768 keys. Skipped 0 keys. Iteration took: 26.772848063s
badger 2019/04/09 09:29:33 DEBUG: LOG Compact. Added 452830 keys. Skipped 0 keys. Iteration took: 23.344841758s
badger 2019/04/09 09:29:42 DEBUG: LOG Compact. Added 452671 keys. Skipped 0 keys. Iteration took: 16.54309142s
badger 2019/04/09 09:29:43 INFO: Written keys: 158100000
badger 2019/04/09 09:29:50 DEBUG: LOG Compact. Added 452831 keys. Skipped 0 keys. Iteration took: 16.776809517s
badger 2019/04/09 09:29:59 DEBUG: LOG Compact. Added 452560 keys. Skipped 0 keys. Iteration took: 16.488058004s
badger 2019/04/09 09:30:06 INFO: Written keys: 158200000
badger 2019/04/09 09:30:06 DEBUG: LOG Compact. Added 452838 keys. Skipped 0 keys. Iteration took: 16.970615826s
badger 2019/04/09 09:32:30 DEBUG: LOG Compact. Added 451984 keys. Skipped 0 keys. Iteration took: 2m23.671994919s
badger 2019/04/09 09:32:31 DEBUG: LOG Compact. Added 452688 keys. Skipped 0 keys. Iteration took: 2m31.98656412s
badger 2019/04/09 09:32:31 INFO: Written keys: 158300000
badger 2019/04/09 09:32:37 DEBUG: LOG Compact. Added 452691 keys. Skipped 0 keys. Iteration took: 5.76146963s
badger 2019/04/09 09:32:37 DEBUG: Discard stats: map[]
badger 2019/04/09 09:32:37 INFO: LOG Compact 2->3, del 7 tables, add 7 tables, took 3m58.644606562s
badger 2019/04/09 09:32:37 INFO: Compaction for level: 2 DONE
badger 2019/04/09 09:32:37 INFO: Got compaction priority: {level:2 score:1.0554185025393963 dropPrefix:[]}
badger 2019/04/09 09:32:37 INFO: Running for level: 2
badger 2019/04/09 09:32:38 INFO: Written keys: 158400000
badger 2019/04/09 09:32:39 DEBUG: LOG Compact. Added 413867 keys. Skipped 0 keys. Iteration took: 2.541820651s
badger 2019/04/09 09:32:42 DEBUG: Discard stats: map[]
badger 2019/04/09 09:32:43 INFO: LOG Compact 1->2, del 9 tables, add 9 tables, took 4m8.89740277s
badger 2019/04/09 09:32:43 INFO: Compaction for level: 1 DONE
badger 2019/04/09 09:32:43 INFO: Got compaction priority: {level:2 score:1.0553033713251352 dropPrefix:[]}
badger 2019/04/09 09:32:43 INFO: Running for level: 2
badger 2019/04/09 09:32:43 INFO: Written keys: 158500000
badger 2019/04/09 09:32:46 INFO: Written keys: 158600000
badger 2019/04/09 09:32:48 DEBUG: LOG Compact. Added 452827 keys. Skipped 0 keys. Iteration took: 5.772092639s
badger 2019/04/09 09:32:49 INFO: Written keys: 158700000
badger 2019/04/09 09:32:53 INFO: Written keys: 158800000
badger 2019/04/09 09:32:54 DEBUG: LOG Compact. Added 452522 keys. Skipped 0 keys. Iteration took: 5.045086839s
badger 2019/04/09 09:32:58 INFO: Written keys: 158900000
badger 2019/04/09 09:32:58 DEBUG: LOG Compact. Added 452800 keys. Skipped 0 keys. Iteration took: 20.913679695s
badger 2019/04/09 09:33:04 DEBUG: Discard stats: map[]
badger 2019/04/09 09:33:05 INFO: LOG Compact 2->3, del 2 tables, add 2 tables, took 21.867949342s
badger 2019/04/09 09:33:05 INFO: Compaction for level: 2 DONE
badger 2019/04/09 09:33:05 INFO: Got compaction priority: {level:2 score:1.0297824680805205 dropPrefix:[]}
badger 2019/04/09 09:33:05 INFO: Running for level: 2
badger 2019/04/09 09:33:13 INFO: Written keys: 159000000
badger 2019/04/09 09:33:15 DEBUG: LOG Compact. Added 452798 keys. Skipped 0 keys. Iteration took: 16.667425964s
badger 2019/04/09 09:33:20 INFO: Written keys: 159100000
badger 2019/04/09 09:33:31 INFO: Written keys: 159200000
badger 2019/04/09 09:33:44 INFO: Written keys: 159300000
badger 2019/04/09 09:33:46 DEBUG: LOG Compact. Added 452793 keys. Skipped 0 keys. Iteration took: 41.079093577s
badger 2019/04/09 09:33:55 INFO: Written keys: 159400000
badger 2019/04/09 09:34:24 DEBUG: LOG Compact. Added 452805 keys. Skipped 0 keys. Iteration took: 1m9.538404177s
badger 2019/04/09 09:34:30 DEBUG: LOG Compact. Added 452831 keys. Skipped 0 keys. Iteration took: 43.760909462s
badger 2019/04/09 09:34:30 INFO: Written keys: 159500000
badger 2019/04/09 09:34:31 DEBUG: LOG Compact. Added 452794 keys. Skipped 0 keys. Iteration took: 7.143073596s
badger 2019/04/09 09:34:33 INFO: Written keys: 159600000
badger 2019/04/09 09:34:33 DEBUG: LOG Compact. Added 452819 keys. Skipped 0 keys. Iteration took: 3.438917632s
badger 2019/04/09 09:34:35 INFO: Written keys: 159700000
badger 2019/04/09 09:34:37 INFO: Written keys: 159800000
badger 2019/04/09 09:34:37 DEBUG: LOG Compact. Added 452813 keys. Skipped 0 keys. Iteration took: 5.956369095s
badger 2019/04/09 09:34:41 INFO: Written keys: 159900000
badger 2019/04/09 09:34:44 INFO: Written keys: 160000000
badger 2019/04/09 09:34:46 DEBUG: LOG Compact. Added 450120 keys. Skipped 0 keys. Iteration took: 12.570694747s
badger 2019/04/09 09:34:47 INFO: Written keys: 160100000
badger 2019/04/09 09:34:47 DEBUG: LOG Compact. Added 452827 keys. Skipped 0 keys. Iteration took: 10.013685108s
badger 2019/04/09 09:34:51 INFO: Written keys: 160200000
badger 2019/04/09 09:34:51 DEBUG: LOG Compact. Added 452831 keys. Skipped 0 keys. Iteration took: 3.454607382s
badger 2019/04/09 09:34:54 INFO: Written keys: 160300000
badger 2019/04/09 09:34:57 INFO: Written keys: 160400000
badger 2019/04/09 09:34:59 INFO: Written keys: 160500000
badger 2019/04/09 09:35:04 DEBUG: Discard stats: map[]
badger 2019/04/09 09:35:05 INFO: LOG Compact 2->3, del 4 tables, add 4 tables, took 2m0.34513301s
badger 2019/04/09 09:35:05 INFO: Compaction for level: 2 DONE
badger 2019/04/09 09:35:05 INFO: Got compaction priority: {level:2 score:1.0042615655809641 dropPrefix:[]}
badger 2019/04/09 09:35:05 INFO: Running for level: 2
badger 2019/04/09 09:35:14 INFO: Written keys: 160600000
badger 2019/04/09 09:35:22 DEBUG: LOG Compact. Added 451836 keys. Skipped 0 keys. Iteration took: 31.382619051s
badger 2019/04/09 09:35:27 DEBUG: Discard stats: map[]
badger 2019/04/09 09:35:27 INFO: LOG Compact 2->3, del 8 tables, add 8 tables, took 2m50.314216374s
badger 2019/04/09 09:35:27 INFO: Compaction for level: 2 DONE
badger 2019/04/09 09:35:29 INFO: Written keys: 160700000
badger 2019/04/09 09:35:30 DEBUG: LOG Compact. Added 452835 keys. Skipped 0 keys. Iteration took: 24.510033411s
badger 2019/04/09 09:35:44 INFO: Written keys: 160800000
badger 2019/04/09 09:35:46 DEBUG: LOG Compact. Added 452835 keys. Skipped 0 keys. Iteration took: 15.913791566s
badger 2019/04/09 09:35:48 INFO: Written keys: 160900000
badger 2019/04/09 09:35:51 INFO: Written keys: 161000000
badger 2019/04/09 09:36:00 INFO: Written keys: 161100000
badger 2019/04/09 09:36:05 INFO: Written keys: 161200000
badger 2019/04/09 09:36:07 DEBUG: LOG Compact. Added 452826 keys. Skipped 0 keys. Iteration took: 21.243700895s
badger 2019/04/09 09:36:12 INFO: Written keys: 161300000
badger 2019/04/09 09:36:46 INFO: Written keys: 161400000
badger 2019/04/09 09:36:49 INFO: Written keys: 161500000
badger 2019/04/09 09:36:52 DEBUG: LOG Compact. Added 452827 keys. Skipped 0 keys. Iteration took: 44.964004552s
badger 2019/04/09 09:37:00 INFO: Written keys: 161600000
badger 2019/04/09 09:37:00 DEBUG: LOG Compact. Added 452833 keys. Skipped 0 keys. Iteration took: 8.193809069s
badger 2019/04/09 09:37:02 INFO: Written keys: 161700000
badger 2019/04/09 09:37:03 DEBUG: LOG Compact. Added 452831 keys. Skipped 0 keys. Iteration took: 2.094871703s
badger 2019/04/09 09:37:04 DEBUG: LOG Compact. Added 438670 keys. Skipped 0 keys. Iteration took: 1.718038225s
badger 2019/04/09 09:37:04 INFO: Written keys: 161800000
badger 2019/04/09 09:37:06 DEBUG: Discard stats: map[]
badger 2019/04/09 09:37:06 INFO: Written keys: 161900000
badger 2019/04/09 09:37:07 INFO: LOG Compact 2->3, del 7 tables, add 7 tables, took 2m1.513656082s
badger 2019/04/09 09:37:07 INFO: Compaction for level: 2 DONE
badger 2019/04/09 09:37:08 INFO: Written keys: 162000000
badger 2019/04/09 09:37:09 INFO: Written keys: 162100000
badger 2019/04/09 09:37:11 INFO: Written keys: 162200000
badger 2019/04/09 09:37:12 INFO: Written keys: 162300000
badger 2019/04/09 09:37:14 INFO: Written keys: 162400000
badger 2019/04/09 09:37:17 INFO: Written keys: 162500000
badger 2019/04/09 09:37:19 INFO: Written keys: 162600000
badger 2019/04/09 09:37:23 INFO: Written keys: 162700000
badger 2019/04/09 09:37:24 INFO: Written keys: 162800000
badger 2019/04/09 09:37:25 INFO: Written keys: 162900000
badger 2019/04/09 09:37:27 INFO: Written keys: 163000000
badger 2019/04/09 09:37:29 INFO: Written keys: 163100000
badger 2019/04/09 09:37:32 INFO: Written keys: 163200000
badger 2019/04/09 09:37:35 INFO: Written keys: 163300000
badger 2019/04/09 09:37:36 INFO: Written keys: 163400000
badger 2019/04/09 09:37:37 INFO: Written keys: 163500000
badger 2019/04/09 09:37:38 INFO: Written keys: 163600000
badger 2019/04/09 09:37:42 INFO: Written keys: 163700000
badger 2019/04/09 09:37:43 INFO: Written keys: 163800000
badger 2019/04/09 09:37:47 INFO: Written keys: 163900000
badger 2019/04/09 09:37:53 INFO: Written keys: 164000000
badger 2019/04/09 09:38:02 INFO: Written keys: 164100000
badger 2019/04/09 09:38:15 INFO: Written keys: 164200000
badger 2019/04/09 09:38:24 INFO: Written keys: 164300000
badger 2019/04/09 09:38:32 INFO: Written keys: 164400000
badger 2019/04/09 09:38:34 INFO: Written keys: 164500000
badger 2019/04/09 09:38:36 INFO: Written keys: 164600000
badger 2019/04/09 09:38:45 INFO: Written keys: 164700000
badger 2019/04/09 09:39:20 INFO: Written keys: 164800000
badger 2019/04/09 09:39:21 INFO: Written keys: 164900000
badger 2019/04/09 09:39:22 INFO: Written keys: 165000000
badger 2019/04/09 09:39:29 INFO: Written keys: 165100000
badger 2019/04/09 09:39:31 INFO: Written keys: 165200000
badger 2019/04/09 09:39:32 INFO: Written keys: 165300000
badger 2019/04/09 09:39:33 INFO: Written keys: 165400000
badger 2019/04/09 09:39:35 INFO: Written keys: 165500000
badger 2019/04/09 09:39:36 INFO: Written keys: 165600000
badger 2019/04/09 09:39:37 INFO: Written keys: 165700000
badger 2019/04/09 09:39:39 INFO: Written keys: 165800000
badger 2019/04/09 09:39:40 INFO: Written keys: 165900000
badger 2019/04/09 09:39:42 INFO: Written keys: 166000000
badger 2019/04/09 09:39:44 INFO: Written keys: 166100000
badger 2019/04/09 09:39:47 INFO: Written keys: 166200000
badger 2019/04/09 09:39:48 INFO: Written keys: 166300000
badger 2019/04/09 09:39:49 INFO: Written keys: 166400000
badger 2019/04/09 09:39:51 INFO: Written keys: 166500000
badger 2019/04/09 09:39:52 INFO: Written keys: 166600000
badger 2019/04/09 09:39:53 INFO: Written keys: 166700000
badger 2019/04/09 09:39:56 INFO: Written keys: 166800000
badger 2019/04/09 09:39:58 INFO: Written keys: 166900000
badger 2019/04/09 09:40:00 INFO: Written keys: 167000000
badger 2019/04/09 09:40:01 INFO: Written keys: 167100000
badger 2019/04/09 09:40:03 INFO: Written keys: 167200000
badger 2019/04/09 09:40:04 INFO: Written keys: 167300000
badger 2019/04/09 09:40:05 INFO: Written keys: 167400000
badger 2019/04/09 09:40:10 INFO: Written keys: 167500000
badger 2019/04/09 09:40:12 INFO: Written keys: 167600000
badger 2019/04/09 09:40:13 INFO: Written keys: 167700000
badger 2019/04/09 09:40:14 INFO: Written keys: 167800000
badger 2019/04/09 09:40:15 INFO: Written keys: 167900000
badger 2019/04/09 09:40:17 INFO: Written keys: 168000000
badger 2019/04/09 09:40:22 INFO: Written keys: 168100000
badger 2019/04/09 09:40:24 INFO: Written keys: 168200000
badger 2019/04/09 09:40:29 INFO: Written keys: 168300000
badger 2019/04/09 09:40:30 INFO: Written keys: 168400000
badger 2019/04/09 09:40:32 INFO: Written keys: 168500000
badger 2019/04/09 09:40:33 INFO: Written keys: 168600000
badger 2019/04/09 09:40:35 INFO: Written keys: 168700000
badger 2019/04/09 09:40:37 INFO: Written keys: 168800000
badger 2019/04/09 09:40:38 INFO: Written keys: 168900000
badger 2019/04/09 09:40:39 INFO: Written keys: 169000000
badger 2019/04/09 09:40:41 INFO: Written keys: 169100000
badger 2019/04/09 09:40:43 INFO: Written keys: 169200000
badger 2019/04/09 09:40:44 INFO: Written keys: 169300000
badger 2019/04/09 09:40:45 INFO: Written keys: 169400000
badger 2019/04/09 09:40:47 INFO: Written keys: 169500000
badger 2019/04/09 09:40:56 INFO: Written keys: 169600000
badger 2019/04/09 09:40:57 INFO: Written keys: 169700000
badger 2019/04/09 09:40:58 INFO: Written keys: 169800000


<< Everything here is the same as before and after, writing keys, no compactions or other logs.

badger 2019/04/09 10:14:08 INFO: Written keys: 270500000
badger 2019/04/09 10:14:10 INFO: Written keys: 270600000
badger 2019/04/09 10:14:11 INFO: Written keys: 270700000
badger 2019/04/09 10:14:13 INFO: Written keys: 270800000
badger 2019/04/09 10:14:38 INFO: Written keys: 270900000
badger 2019/04/09 10:14:52 INFO: Written keys: 271000000
badger 2019/04/09 10:15:07 INFO: Written keys: 271100000
badger 2019/04/09 10:15:26 INFO: Written keys: 271200000
badger 2019/04/09 10:15:29 DEBUG: Storing value log head: {Fid:85 Len:45 Offset:170270550}
badger 2019/04/09 10:15:31 INFO: Written keys: 271300000
badger 2019/04/09 10:15:41 INFO: Written keys: 271400000
badger 2019/04/09 10:15:47 INFO: Written keys: 271500000
badger 2019/04/09 10:15:51 INFO: Written keys: 271600000
badger 2019/04/09 10:16:08 INFO: Written keys: 271700000
badger 2019/04/09 10:16:12 INFO: Written keys: 271800000
badger 2019/04/09 10:16:16 INFO: Written keys: 271900000
badger 2019/04/09 10:16:32 INFO: Written keys: 272000000
badger 2019/04/09 10:16:52 INFO: Written keys: 272100000
badger 2019/04/09 10:17:08 DEBUG: Storing value log head: {Fid:86 Len:45 Offset:68108193}
badger 2019/04/09 10:17:45 INFO: Written keys: 272200000
badger 2019/04/09 10:19:03 INFO: Written keys: 272300000
badger 2019/04/09 10:19:04 INFO: Written keys: 272400000
badger 2019/04/09 10:19:10 INFO: Written keys: 272500000
badger 2019/04/09 10:19:12 INFO: Written keys: 272600000
badger 2019/04/09 10:19:15 INFO: Written keys: 272700000
badger 2019/04/09 10:19:18 INFO: Written keys: 272800000
badger 2019/04/09 10:19:22 DEBUG: Storing value log head: {Fid:86 Len:45 Offset:136216431}
badger 2019/04/09 10:19:38 INFO: Written keys: 272900000
badger 2019/04/09 10:19:53 INFO: Written keys: 273000000
badger 2019/04/09 10:20:38 INFO: Written keys: 273100000
badger 2019/04/09 10:21:20 INFO: Written keys: 273200000
badger 2019/04/09 10:21:33 INFO: Written keys: 273300000
badger 2019/04/09 10:21:52 INFO: Written keys: 273400000
badger 2019/04/09 10:21:53 INFO: Written keys: 273500000
badger 2019/04/09 10:21:55 INFO: Written keys: 273600000
badger 2019/04/09 10:21:57 INFO: Written keys: 273700000
badger 2019/04/09 10:21:59 INFO: Written keys: 273800000
badger 2019/04/09 10:22:00 INFO: Written keys: 273900000
badger 2019/04/09 10:22:02 INFO: Written keys: 274000000
badger 2019/04/09 10:22:03 INFO: Written keys: 274100000
badger 2019/04/09 10:22:04 INFO: Written keys: 274200000
badger 2019/04/09 10:22:06 INFO: Written keys: 274300000
badger 2019/04/09 10:22:07 INFO: Written keys: 274400000
badger 2019/04/09 10:22:09 INFO: Written keys: 274500000
badger 2019/04/09 10:22:10 INFO: Written keys: 274600000
badger 2019/04/09 10:22:12 INFO: Written keys: 274700000
badger 2019/04/09 10:22:13 INFO: Written keys: 274800000
badger 2019/04/09 10:22:15 INFO: Written keys: 274900000
badger 2019/04/09 10:22:17 INFO: Written keys: 275000000
badger 2019/04/09 10:22:18 INFO: Written keys: 275100000
badger 2019/04/09 10:22:20 INFO: Written keys: 275200000
badger 2019/04/09 10:22:21 INFO: Written keys: 275300000
badger 2019/04/09 10:22:23 INFO: Written keys: 275400000
badger 2019/04/09 10:22:24 INFO: Written keys: 275500000
badger 2019/04/09 10:22:26 INFO: Written keys: 275600000
badger 2019/04/09 10:22:28 INFO: Written keys: 275700000
badger 2019/04/09 10:22:30 INFO: Written keys: 275800000
badger 2019/04/09 10:22:31 INFO: Written keys: 275900000
badger 2019/04/09 10:22:33 INFO: Written keys: 276000000
badger 2019/04/09 10:22:35 INFO: Written keys: 276100000
badger 2019/04/09 10:22:36 INFO: Written keys: 276200000
badger 2019/04/09 10:22:38 INFO: Written keys: 276300000
badger 2019/04/09 10:22:39 INFO: Written keys: 276400000
badger 2019/04/09 10:22:41 INFO: Written keys: 276500000
badger 2019/04/09 10:22:43 INFO: Written keys: 276600000
badger 2019/04/09 10:22:44 INFO: Written keys: 276700000
badger 2019/04/09 10:22:46 INFO: Written keys: 276800000
badger 2019/04/09 10:22:48 INFO: Written keys: 276900000
badger 2019/04/09 10:22:49 INFO: Written keys: 277000000
badger 2019/04/09 10:22:51 INFO: Written keys: 277100000
badger 2019/04/09 10:22:54 INFO: Written keys: 277200000
badger 2019/04/09 10:22:56 INFO: Written keys: 277300000
badger 2019/04/09 10:22:58 INFO: Written keys: 277400000
badger 2019/04/09 10:23:00 INFO: Written keys: 277500000
badger 2019/04/09 10:23:02 INFO: Written keys: 277600000
badger 2019/04/09 10:23:04 INFO: Written keys: 277700000
badger 2019/04/09 10:23:10 INFO: Written keys: 277800000
badger 2019/04/09 10:23:13 INFO: Written keys: 277900000
badger 2019/04/09 10:23:15 INFO: Written keys: 278000000
badger 2019/04/09 10:23:17 INFO: Written keys: 278100000
badger 2019/04/09 10:23:19 INFO: Written keys: 278200000
badger 2019/04/09 10:23:23 INFO: Written keys: 278300000
badger 2019/04/09 10:23:26 INFO: Written keys: 278400000
badger 2019/04/09 10:23:30 INFO: Written keys: 278500000
badger 2019/04/09 10:23:33 INFO: Written keys: 278600000
badger 2019/04/09 10:24:50 DEBUG: Storing value log head: {Fid:87 Len:45 Offset:34054074}
badger 2019/04/09 10:24:50 INFO: Got compaction priority: {level:0 score:1 dropPrefix:[]}
badger 2019/04/09 10:24:50 INFO: Running for level: 0
badger 2019/04/09 10:25:00 INFO: Written keys: 278700000
badger 2019/04/09 10:25:15 DEBUG: LOG Compact. Added 450333 keys. Skipped 0 keys. Iteration took: 24.44662224s
badger 2019/04/09 10:25:17 DEBUG: Storing value log head: {Fid:87 Len:45 Offset:102162312}
badger 2019/04/09 10:25:17 INFO: Written keys: 278800000
badger 2019/04/09 10:25:19 INFO: Written keys: 278900000
badger 2019/04/09 10:25:21 INFO: Written keys: 279000000
badger 2019/04/09 10:25:23 INFO: Written keys: 279100000
badger 2019/04/09 10:25:24 INFO: Written keys: 279200000
badger 2019/04/09 10:25:25 DEBUG: LOG Compact. Added 450487 keys. Skipped 0 keys. Iteration took: 9.323000267s
badger 2019/04/09 10:25:26 INFO: Written keys: 279300000
badger 2019/04/09 10:25:28 INFO: Written keys: 279400000
badger 2019/04/09 10:25:30 INFO: Written keys: 279500000
badger 2019/04/09 10:25:33 INFO: Written keys: 279600000
badger 2019/04/09 10:25:38 DEBUG: LOG Compact. Added 452118 keys. Skipped 0 keys. Iteration took: 13.454240035s
badger 2019/04/09 10:25:39 INFO: Written keys: 279700000
badger 2019/04/09 10:25:49 DEBUG: LOG Compact. Added 450507 keys. Skipped 0 keys. Iteration took: 11.414441338s
badger 2019/04/09 10:25:50 INFO: Written keys: 279800000
badger 2019/04/09 10:25:57 INFO: Written keys: 279900000
badger 2019/04/09 10:25:59 DEBUG: LOG Compact. Added 450826 keys. Skipped 0 keys. Iteration took: 9.784568705s
badger 2019/04/09 10:26:11 DEBUG: LOG Compact. Added 451369 keys. Skipped 0 keys. Iteration took: 11.785421343s
badger 2019/04/09 10:26:12 INFO: Written keys: 280000000
badger 2019/04/09 10:26:28 DEBUG: LOG Compact. Added 451111 keys. Skipped 0 keys. Iteration took: 17.22481685s
badger 2019/04/09 10:26:34 INFO: Written keys: 280100000
badger 2019/04/09 10:27:02 DEBUG: LOG Compact. Added 451794 keys. Skipped 0 keys. Iteration took: 33.256204506s
badger 2019/04/09 10:27:03 DEBUG: LOG Compact. Added 38226 keys. Skipped 0 keys. Iteration took: 1.350499693s
badger 2019/04/09 10:27:04 INFO: Written keys: 280200000
badger 2019/04/09 10:27:45 DEBUG: Discard stats: map[]
badger 2019/04/09 10:27:46 INFO: Got compaction priority: {level:1 score:2.0631032437086105 dropPrefix:[]}
badger 2019/04/09 10:27:46 INFO: Running for level: 1
badger 2019/04/09 10:27:48 INFO: LOG Compact 0->1, del 9 tables, add 9 tables, took 2m57.590923911s
badger 2019/04/09 10:27:49 INFO: Compaction for level: 0 DONE
badger 2019/04/09 10:27:49 INFO: Got compaction priority: {level:1 score:1.8078946433961391 dropPrefix:[]}
badger 2019/04/09 10:27:49 INFO: Running for level: 1
badger 2019/04/09 10:32:22 DEBUG: Storing value log head: {Fid:87 Len:45 Offset:170270550}
badger 2019/04/09 10:32:32 INFO: Written keys: 280300000
badger 2019/04/09 10:32:36 DEBUG: LOG Compact. Added 452476 keys. Skipped 0 keys. Iteration took: 4m49.726828336s
badger 2019/04/09 10:32:37 DEBUG: LOG Compact. Added 452559 keys. Skipped 0 keys. Iteration took: 4m47.244480324s
badger 2019/04/09 10:32:55 INFO: Written keys: 280400000
badger 2019/04/09 10:33:45 INFO: Written keys: 280500000
badger 2019/04/09 10:34:03 DEBUG: LOG Compact. Added 452016 keys. Skipped 0 keys. Iteration took: 1m27.119968959s
badger 2019/04/09 10:34:58 INFO: Written keys: 280600000
badger 2019/04/09 10:35:00 DEBUG: LOG Compact. Added 452565 keys. Skipped 0 keys. Iteration took: 2m23.389648841s
badger 2019/04/09 10:35:41 DEBUG: LOG Compact. Added 452025 keys. Skipped 0 keys. Iteration took: 1m37.567704944s
badger 2019/04/09 10:36:15 INFO: Written keys: 280700000
badger 2019/04/09 10:36:20 DEBUG: LOG Compact. Added 452565 keys. Skipped 0 keys. Iteration took: 1m19.336362665s
badger 2019/04/09 10:36:30 INFO: Written keys: 280800000
badger 2019/04/09 10:36:31 DEBUG: Storing value log head: {Fid:88 Len:45 Offset:68108193}
badger 2019/04/09 10:36:33 DEBUG: LOG Compact. Added 452649 keys. Skipped 0 keys. Iteration took: 12.769452721s
badger 2019/04/09 10:36:33 INFO: Written keys: 280900000
badger 2019/04/09 10:37:06 DEBUG: LOG Compact. Added 452529 keys. Skipped 0 keys. Iteration took: 1m25.089038462s
badger 2019/04/09 10:37:16 INFO: Written keys: 281000000
badger 2019/04/09 10:37:47 DEBUG: LOG Compact. Added 452450 keys. Skipped 0 keys. Iteration took: 1m14.176019973s
badger 2019/04/09 10:38:19 INFO: Written keys: 281100000
badger 2019/04/09 10:38:39 DEBUG: LOG Compact. Added 452619 keys. Skipped 0 keys. Iteration took: 1m33.339960134s
badger 2019/04/09 10:40:52 DEBUG: LOG Compact. Added 452700 keys. Skipped 0 keys. Iteration took: 3m4.686752056s
badger 2019/04/09 10:41:01 INFO: Written keys: 281200000
badger 2019/04/09 10:41:11 INFO: Written keys: 281300000
badger 2019/04/09 10:41:14 DEBUG: LOG Compact. Added 452829 keys. Skipped 0 keys. Iteration took: 2m34.07834658s
badger 2019/04/09 10:41:15 INFO: Written keys: 281400000
badger 2019/04/09 10:41:25 INFO: Written keys: 281500000
badger 2019/04/09 10:41:28 INFO: Written keys: 281600000
badger 2019/04/09 10:41:32 INFO: Written keys: 281700000
badger 2019/04/09 10:41:35 DEBUG: LOG Compact. Added 452707 keys. Skipped 0 keys. Iteration took: 43.56474419s
badger 2019/04/09 10:41:38 INFO: Written keys: 281800000
badger 2019/04/09 10:41:44 INFO: Written keys: 281900000
badger 2019/04/09 10:41:54 INFO: Written keys: 282000000
badger 2019/04/09 10:41:59 INFO: Written keys: 282100000
badger 2019/04/09 10:42:12 INFO: Written keys: 282200000
badger 2019/04/09 10:42:14 DEBUG: LOG Compact. Added 452444 keys. Skipped 0 keys. Iteration took: 38.739600083s
badger 2019/04/09 10:42:47 DEBUG: LOG Compact. Added 452831 keys. Skipped 0 keys. Iteration took: 1m33.366930105s
badger 2019/04/09 10:43:19 INFO: Written keys: 282300000
badger 2019/04/09 10:45:09 DEBUG: Storing value log head: {Fid:88 Len:45 Offset:136216431}
badger 2019/04/09 10:45:30 DEBUG: LOG Compact. Added 411844 keys. Skipped 0 keys. Iteration took: 3m15.390909125s
badger 2019/04/09 10:45:31 INFO: Written keys: 282400000
badger 2019/04/09 10:45:32 DEBUG: Discard stats: map[]
badger 2019/04/09 10:45:33 INFO: Written keys: 282500000
badger 2019/04/09 10:45:33 INFO: LOG Compact 1->2, del 9 tables, add 9 tables, took 17m44.012847441s
badger 2019/04/09 10:45:33 INFO: Compaction for level: 1 DONE
badger 2019/04/09 10:45:33 INFO: Got compaction priority: {level:1 score:1.5526857934892178 dropPrefix:[]}
badger 2019/04/09 10:45:33 INFO: Running for level: 1
badger 2019/04/09 10:45:34 DEBUG: LOG Compact. Added 451794 keys. Skipped 0 keys. Iteration took: 2m47.448085799s
badger 2019/04/09 10:45:35 INFO: Written keys: 282600000
badger 2019/04/09 10:45:38 INFO: Written keys: 282700000
badger 2019/04/09 10:45:41 INFO: Written keys: 282800000
badger 2019/04/09 10:45:43 INFO: Written keys: 282900000
badger 2019/04/09 10:45:45 INFO: Written keys: 283000000
badger 2019/04/09 10:45:48 INFO: Written keys: 283100000
badger 2019/04/09 10:45:58 DEBUG: LOG Compact. Added 452257 keys. Skipped 0 keys. Iteration took: 24.487762411s
badger 2019/04/09 10:45:58 DEBUG: LOG Compact. Added 452580 keys. Skipped 0 keys. Iteration took: 23.496445715s
badger 2019/04/09 10:45:58 INFO: Written keys: 283200000
badger 2019/04/09 10:46:06 INFO: Written keys: 283300000
badger 2019/04/09 10:46:11 INFO: Written keys: 283400000
badger 2019/04/09 10:46:20 INFO: Written keys: 283500000
badger 2019/04/09 10:46:27 DEBUG: LOG Compact. Added 448291 keys. Skipped 0 keys. Iteration took: 29.49049532s
badger 2019/04/09 10:46:30 INFO: Written keys: 283600000
badger 2019/04/09 10:46:36 DEBUG: LOG Compact. Added 452167 keys. Skipped 0 keys. Iteration took: 38.461722817s
badger 2019/04/09 10:46:39 INFO: Written keys: 283700000
badger 2019/04/09 10:46:47 INFO: Written keys: 283800000
badger 2019/04/09 10:46:50 DEBUG: Discard stats: map[]
badger 2019/04/09 10:46:50 INFO: Written keys: 283900000
badger 2019/04/09 10:46:53 INFO: LOG Compact 1->2, del 10 tables, add 10 tables, took 19m6.756691916s
badger 2019/04/09 10:46:53 INFO: Compaction for level: 1 DONE
badger 2019/04/09 10:46:53 INFO: Got compaction priority: {level:1 score:1.2974771112203598 dropPrefix:[]}
badger 2019/04/09 10:46:53 INFO: Running for level: 1
badger 2019/04/09 10:47:02 INFO: Written keys: 284000000
badger 2019/04/09 10:47:33 INFO: Written keys: 284100000
badger 2019/04/09 10:48:26 DEBUG: LOG Compact. Added 452681 keys. Skipped 0 keys. Iteration took: 1m49.217066107s
badger 2019/04/09 10:51:51 INFO: Written keys: 284200000
badger 2019/04/09 10:51:57 DEBUG: LOG Compact. Added 452583 keys. Skipped 0 keys. Iteration took: 5m3.233626754s
badger 2019/04/09 10:52:01 DEBUG: LOG Compact. Added 452505 keys. Skipped 0 keys. Iteration took: 3m34.871618574s
badger 2019/04/09 10:52:06 INFO: Written keys: 284300000
badger 2019/04/09 10:52:14 DEBUG: LOG Compact. Added 451506 keys. Skipped 0 keys. Iteration took: 17.684215365s
badger 2019/04/09 10:52:16 DEBUG: LOG Compact. Added 410814 keys. Skipped 0 keys. Iteration took: 15.586605395s
badger 2019/04/09 10:52:18 INFO: Written keys: 284400000
badger 2019/04/09 10:53:56 DEBUG: Storing value log head: {Fid:89 Len:45 Offset:34054074}
badger 2019/04/09 10:53:58 DEBUG: Discard stats: map[]
badger 2019/04/09 10:53:58 INFO: LOG Compact 1->2, del 5 tables, add 5 tables, took 8m24.936729386s
badger 2019/04/09 10:53:59 INFO: Compaction for level: 1 DONE
badger 2019/04/09 10:53:59 INFO: Got compaction priority: {level:2 score:1.0550055850297213 dropPrefix:[]}
badger 2019/04/09 10:53:59 INFO: Running for level: 2
Killed: 9

badger info for the above execution.

[EXTRA]
[2019-04-09T10:52:06-05:00] 002186.sst    68 MB
[2019-04-09T10:52:27-05:00] 002188.sst    68 MB
[2019-04-09T10:54:01-05:00] 002190.sst      0 B
[2019-04-09T06:50:41-05:00] LOCK            5 B

[Summary]
Level 0 size:       323 MB
Level 1 size:       348 MB
Level 2 size:       2.8 GB
Level 3 size:        11 GB
Total index size:    14 GB
Value log size:      23 GB

Abnormalities:
4 extra files.
0 missing files.
0 empty files.
0 truncated manifests.

(Manish R Jain) #6

I think it is suffering from the same issue. BatchWriter needs a Throttle. @ashishgoswami is working on it.


(Tom) #7

Version information

Ubuntu 18.04 VM

$ go version
go version go1.12.1 linux/amd64

$ ls -lah ~/go/bin/badger
-rwxrwxr-x 1 ubuntu ubuntu 13M Apr  4 05:29 /home/ubuntu/go/bin/badger

$ md5sum ~/go/bin/badger 
45d2992b8431e245511ebf76a58283a0  /home/ubuntu/go/bin/badger

$ file ~/go/bin/badger 
/home/ubuntu/go/bin/badger: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked, interpreter /lib64/l, not stripped

macOS

$ go version
go version go1.11 darwin/amd64

$ ls -lah badger 
-rwxr-xr-x  1 username  2075806812    12M Apr  9 06:50 badger*

$ md5sum badger 
6df4bb8860120472f687df15cbe6aba7  badger

$ file badger
badger: Mach-O 64-bit executable x86_64

(Tom) #8

Thanks much for the response and looking into this.