Investigate why bridge/full nodes sometimes hang for 1 minute at a time on full 2MB+ Robusta

[musalbas]

Starting a discussion on this to share findings.

[musalbas]

I've been doing some benchmarking experiments with badger v2 and v4 and I have some interesting observations about write performance and compaction I can share logs on etc later.

Some of these could be invalidated after further experiments, but the initial tl;dr is that:

• Batched Badger write performance is 600,000+ keys per second, which seems fine for now for 2MB and 8MB blocks. Assuming 2MB blocks need to write 128x128x3 CIDs, it takes ~80ms, and assuming 8MB blocks need to write 256x256x3 CIDs, it takes 300-400ms.
• Background compaction (runCompactor) seems to be only heavy when you're overwriting keys that you already wrote to before (see two versions of code below). When you're writing only new keys, I couldn't observe it running at all.
• Even so, compaction seems quite fast (like ~20% overhead over write time, e.g. when doing a batch of 7 writes of 1M keys that takes 1.5 seconds each, compactor then runs for ~1s on v2 when using code below where compactor runs a lot).
• I cannot replicate any case where writing is blocked, let alone any case where writing is blocked by a minute. So the reason why Puts are being blocked in celestia-node could be a different reason or a low-hanging bug.

---

Code where compactor runs a lot:

package main

import (
	"fmt"
	"log"
	"math/rand"
	"strconv"
	"time"

	"net/http"
	_ "net/http/pprof"

	badger "github.com/dgraph-io/badger/v2"
)

func main() {
	go func() {
		fmt.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	db, err := badger.Open(badger.DefaultOptions("db"))
	if err != nil {
		log.Fatal(err)
	}
	defer db.Close()

	k := make([]byte, 32)
	v := make([]byte, 512)
	rand.Read(k)
	rand.Read(v)

	for i := 0; i < 1000000; i++ {
		wb := db.NewWriteBatch()
		st := time.Now()
		for j := 0; j < 1000000; j++ {

			wb.Set([]byte(strconv.Itoa(j)), []byte(strconv.Itoa(i)))
		}

		if err := wb.Flush(); err != nil {
			log.Fatal(err)
		}

		//db.Sync()

		log.Printf(time.Since(st).String())
	}
}

Code where it doesn't:

package main

import (
	"fmt"
	"log"
	"math/rand"
	"time"

	"net/http"
	_ "net/http/pprof"

	badger "github.com/dgraph-io/badger/v2"
)

func main() {
	go func() {
		fmt.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	db, err := badger.Open(badger.DefaultOptions("db"))
	if err != nil {
		log.Fatal(err)
	}
	defer db.Close()

	k := make([]byte, 32)
	v := make([]byte, 512)

	for i := 0; i < 1000000; i++ {
		wb := db.NewWriteBatch()
		st := time.Now()
		for j := 0; j < 1000000; j++ {
			rand.Read(k)
			rand.Read(v)

			wb.Set(k, v)
		}

		if err := wb.Flush(); err != nil {
			log.Fatal(err)
		}

		//db.Sync()

		log.Printf(time.Since(st).String())
	}
}

[Wondertan]

@musalbas, thank you for testing this out. Your findings confirm my interpretation of the badger code and its non-blocking design. To find the real reason behind hangs, I made this tool: #2482. Check it out!

I have yet to start investigating using the tool and I also encourage you to try and suggest any features/improvements to ease the process and make it more future-proof.

[Wondertan]

Before starting any further work, I will take all the optimization in a single PR because the current avg time is 3.4 secs which takes a while to get any meaningful results. Also, I will take a DO machine to test things on, and the ultimate aim/test would be running it for a whole week without any hiccups.

[Wondertan]

What we know so far from testing on Robusta is that the Badgerv2 with our configuration does not handle such load and causes OOMs after a certain period of time. We also know that Badgerv4 helps with it, just by updating the version.

[Wondertan]

With the tool we were able to reproduce hangs:

TotalWritten 30490
TotalWritingTime 12h18m53.374603526s
MaxTime 4m10.526019869s
MinTime 1.045032109s
AvgTime 1.454029996s

[musalbas]

BTW is this with optimisations and v4 or without, and what is the ODS size? What's the setup where you replicated the hang?

[Wondertan]

This is without any optimizations running over main with v2. The ODS size 64

[Wondertan]

The next step is running v4 with optimizations

[Wondertan]

And then tweaking knobs :party-parrot:

cc @walldiss

[Wondertan]

Passing all further testing to @walldiss

[Wondertan]

We found two issues:

• High-load on badger made it block the compaction
  • Using a separate badger instance with aggressive L0 compaction solved this(fix(share/eds)!: use separate badger for inverted index #2517)
• Dagstore GC blocked write every now and then
  • Removing GC solved it. It's also unnecessary as its using transients(fix(share/eds): turn off eds store dagstore gc by default #2529 )

So we can safely close the discussion