Badger become slower and slower after bulkwrite and Iterator 1000 key again and again

What version of Go are you using (go version)?

$ go version
go version go1.13.1 darwin/amd64

What operating system are you using?

ubuntu 1804

What version of Badger are you using?

v2.0.3

Does this issue reproduce with the latest master?

do not tested.

Steps to Reproduce the issue

package main

import (
	"github.com/dgraph-io/badger"
	"os"
	"strconv"
	"fmt"
	"time"
)

func main(){
	dir:="/tmp/db_test/bug1"
	err:=os.RemoveAll(dir)
	if err!=nil && os.IsNotExist(err)==false{
		panic(err)
	}
	err=os.MkdirAll(dir,0777)
	if err!=nil{
		panic(err)
	}
	thisDb,err:=badger.Open(badger.DefaultOptions(dir))
	if err!=nil{
		panic(err)
	}
	st:=time.Now()
	for i:=0;i<1e5;i++ {
		err:=thisDb.Update(func(tx *badger.Txn)error{
			for a1:=0;a1<1000;a1++{
				err:=tx.Set([]byte(strconv.Itoa(a1)),[]byte(strconv.Itoa(i)))
				if err!=nil{
					return err
				}
			}
			return nil
		})
		if err!=nil{
			panic(err)
		}
		err=thisDb.View(func(txn *badger.Txn)error{
			it:=txn.NewIterator(badger.DefaultIteratorOptions)
			defer it.Close()
			for it.Rewind(); it.Valid(); it.Next() {
			}
			return nil
		})
		if err!=nil{
			panic(err)
		}
		if i%100==0{
			fmt.Println("write",i,time.Since(st),float64(i)/time.Since(st).Seconds())
		}
	}
}

What did you do?

bulkwrite and Iterator 1000 key with different value again and again.

What did you expect to see?

Badger have a stable performance.

What did you see instead?

Badger become slower and slower very quickly.

write 0 6.433871ms 0
write 100 2.064775108s 48.431420702671865
write 200 6.908348445s 28.950478748877696
write 300 14.215100242s 21.104317961168412
write 400 24.276158279s 16.477071553252784
write 500 37.195009263s 13.442663596436361
write 600 52.480690329s 11.432776401336401
write 700 1m9.790894105s 10.029961733094646
write 800 1m29.631318416s 8.92545164214274
write 900 1m51.614999564s 8.063432338264798
write 1000 2m16.907256116s 7.304214743589038
write 1100 2m43.715884614s 6.718957060547765

ps:

  • call db.RunValueLogGC every 10s will not solve this problem.
  • The performance is stable if I only write do not Iterator. Maybe some bug relavtive to Iterator lifetime.

While you’re only doing 1000 writes each time, you’re iterating over more and more data, so it is taking longer.

No, The data set is 1000 rows only. Those keys is the same 1000 keys. It only iterate 1000 keys.

Not internally. In LSM trees, keys don’t get overwritten. They get added, and only after compaction would they be discarded. Internally, every iteration is going through all the previous keys your test added, even if it is only returning the latest versions of those 1000 keys.

I use this algorithm(write and iterator again and again) to record the position of an internally index thread so I can start index data at correct position after process restart.
Is there any solution to this problem? google gcp bigtable have similar problem, so I start try other database. mysql/sqlite3 do not have this kind of problem.
Is there some internally data that record number of valid version of keys and number of all version of keys, and start compaction after the valid ratio is too low?
Can I call some methods to start compaction myself?

I wonder if a B+ tree solution might be a better fit for you. Have you tried BoltDB?

Gcp mysql is correct and fast to me, but start/install a new instance is too complex for my new project, so I want an embed database.
Sqlite3 is correct. But it is very slow.
https://github.com/boltdb/bolt have deadlock bug when I try to copy data in same database.

Read-only transactions and read-write transactions should not depend on one another and generally shouldn’t be opened simultaneously in the same goroutine. This can cause a deadlock as the read-write transaction needs to periodically re-map the data file but it cannot do so while a read-only transaction is open.

In this cases, I know I will write same keys and read them again and again, is there any methods I can call to start the key compaction?

There’s a DB.Flatten method, that you can try.

I tried add DB.Flatten and DB.RunValueLogGC every 100 operations, it is better, but problem is not solved.

badger 2020/07/25 02:39:23 INFO: Level: 0. 0 B Size. 0 B Max.
badger 2020/07/25 02:39:23 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:39:23 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:39:23 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:39:23 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:39:23 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:39:23 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:39:23 INFO: All tables consolidated into one level. Flattening done.
write 100 1000 1.019063664s 98.12926766454314
badger 2020/07/25 02:39:25 INFO:
badger 2020/07/25 02:39:25 INFO: Level: 0. 0 B Size. 0 B Max.
badger 2020/07/25 02:39:25 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:39:25 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:39:25 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:39:25 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:39:25 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:39:25 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:39:25 INFO: All tables consolidated into one level. Flattening done.
write 200 1000 3.218679077s 62.1372897655249
badger 2020/07/25 02:39:29 INFO:
badger 2020/07/25 02:39:29 INFO: Level: 0. 0 B Size. 0 B Max.
badger 2020/07/25 02:39:29 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:39:29 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:39:29 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:39:29 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:39:29 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:39:29 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:39:29 INFO: All tables consolidated into one level. Flattening done.
write 300 1000 7.210104937s 41.608270522311074
badger 2020/07/25 02:41:16 INFO:
badger 2020/07/25 02:41:16 INFO: Level: 0. 0 B Size. 0 B Max.
badger 2020/07/25 02:41:16 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:41:16 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:41:16 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:41:16 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:41:16 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:41:16 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:41:16 INFO: All tables consolidated into one level. Flattening done.
write 1100 1000 1m54.228532736s 9.629818160925609
badger 2020/07/25 02:56:08 INFO:
badger 2020/07/25 02:56:08 INFO: Level: 0. 55 MB Size. 0 B Max.
badger 2020/07/25 02:56:08 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:56:08 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:56:08 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:56:08 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:56:08 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:56:08 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:56:08 INFO: All tables consolidated into one level. Flattening done.
write 3500 1000 16m45.892792378s 3.479496051852332
badger 2020/07/25 02:57:07 INFO:
badger 2020/07/25 02:57:07 INFO: Level: 0. 55 MB Size. 0 B Max.
badger 2020/07/25 02:57:07 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:57:07 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:57:07 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:57:07 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:57:07 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:57:07 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:57:07 INFO: All tables consolidated into one level. Flattening done.
write 3600 1000 17m45.103696368s 3.379952592402103
badger 2020/07/25 02:58:09 INFO:
badger 2020/07/25 02:58:09 INFO: Level: 0. 55 MB Size. 0 B Max.
badger 2020/07/25 02:58:09 INFO: Level: 1. 0 B Size. 268 MB Max.
badger 2020/07/25 02:58:09 INFO: Level: 2. 0 B Size. 2.7 GB Max.
badger 2020/07/25 02:58:09 INFO: Level: 3. 0 B Size. 27 GB Max.
badger 2020/07/25 02:58:09 INFO: Level: 4. 0 B Size. 268 GB Max.
badger 2020/07/25 02:58:09 INFO: Level: 5. 0 B Size. 2.7 TB Max.
badger 2020/07/25 02:58:09 INFO: Level: 6. 0 B Size. 27 TB Max.
badger 2020/07/25 02:58:09 INFO: All tables consolidated into one level. Flattening done.
write 3700 1000 18m46.633006585s 3.284121784167574

Internally, every iteration is going through all the previous keys your test added, even if it is only returning the latest versions of those 1000 keys.

I try to open a database with a lot of write and iterator, then I use follow options to iterator over all the data:

		opt:=badger.DefaultIteratorOptions
		opt.AllVersions = true
		opt.InternalAccess = true

The rows number is 1000.But the iterator is slow any way. (about 0.3s one iterator)
Is there any method to get the internally iteration number?

Flatten isn’t doing much. All of your data hasn’t even made to levels yet.

Thanks for your help, I found a solution:

  • Call DB.DropPrefix() on an not-exist prefix(like 0xff) can solve this problem.

  • The iteration delay will drop to less then 1ms, after I call DB.DropPrefix().

  • ps: I found that when I seen log like “badger 2020/07/25 04:59:27 DEBUG: LOG Compact. Added 1001 keys. Skipped 6538005 keys. Iteration took: 3.507171461s” ,the iteration delay will drop, then I search it in the source code, I found that i can only trigger it with DB.DropPrefix() call.

2 Likes
  • DB.DropPrefix() can not be called in background thread. The DB.Update call will “Writes are blocked, possibly due to DropAll or Close”.

  • Another benefit by call DB.DropPrefix() and DB.RunValueLogGC(), it can reduce the file size in that directory from 300M+ to 100KB.

  • So we may need to trigger “LOG Compact” manually to reduce the file size and reduce

Yes, drop prefix is a stop-world operation and your writes will get blocked while this is happening.

Drop prefix with a non existent prefix is causing the whole LSM tree to compact which removes all the stale data and hence improving read speed.

We actually want to support this in future. A user should be able to cause a forced compaction to clean up the LSM Tree.