Badger: Infinite recursion in Item.yieldItemValue ?

[stephane-martin]

Hi,

I face a difficult to debug problem with badger. It happens in the following situation:

• ingest a lot of data (say 1M key-values)
• delete that data
• stop the program (properly closing the badger database)
• relaunch the program

Then it can happen that when the program reopens the badger database, go panics with a "runtime: goroutine stack exceeds 1000000000-byte limit".

Further tries to start the program then always face a panic.

The problem might be in my code of course, but I can't find anything strange. I disabled everything except opening the database and iterating over key values, and panic still happens.

The traces show:

goroutine 1 [running]:
runtime.makeslice(0xef4340, 0x28, 0x28, 0xc425764000, 0x0, 0x7ff73adb46c8)
        /usr/local/go/src/runtime/slice.go:46 +0xf7 fp=0xc44cd70348 sp=0xc44cd70340 pc=0x4470f7
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*blockIterator).parseKV(0xc42d3aa990, 0xf00140000, 0xffffffff)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:114 +0x4bf fp=0xc44cd70430 sp=0xc44cd70348 pc=0xc749cf
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*blockIterator).Next(0xc42d3aa990)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:154 +0x191 fp=0xc44cd70480 sp=0xc44cd70430 pc=0xc74bd1
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*blockIterator).Init(0xc42d3aa990)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:54 +0x3d fp=0xc44cd70498 sp=0xc44cd70480 pc=0xc7414d
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*blockIterator).Seek(0xc42d3aa990, 0xc42d3a4cc0, 0x2b, 0x30, 0x0)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:84 +0x153 fp=0xc44cd704e8 sp=0xc44cd70498 pc=0xc74303
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*Iterator).seekHelper(0xc42d3a2600, 0x0, 0xc42d3a4cc0, 0x2b, 0x30)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:270 +0x11f fp=0xc44cd70550 sp=0xc44cd704e8 pc=0xc7551f
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*Iterator).seekFrom(0xc42d3a2600, 0xc42d3a4cc0, 0x2b, 0x30, 0x0)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:300 +0x12f fp=0xc44cd705b8 sp=0xc44cd70550 pc=0xc756bf
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*Iterator).seek(0xc42d3a2600, 0xc42d3a4cc0, 0x2b, 0x30)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:316 +0x55 fp=0xc44cd705f0 sp=0xc44cd705b8 pc=0xc75815
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table.(*Iterator).Seek(0xc42d3a2600, 0xc42d3a4cc0, 0x2b, 0x30)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/table/iterator.go:417 +0x82 fp=0xc44cd70620 sp=0xc44cd705f0 pc=0xc75f92
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger.(*levelHandler).get(0xc4203ae8a0, 0xc42d3a4cc0, 0x2b, 0x30, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/level_handler.go:253 +0x265 fp=0xc44cd706f8 sp=0xc44cd70620 pc=0xc8acc5
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger.(*levelsController).get(0xc420393e30, 0xc42d3a4cc0, 0x2b, 0x30, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/levels.go:727 +0xf6 fp=0xc44cd70820 sp=0xc44cd706f8 pc=0xc90e76
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger.(*DB).get(0xc42040c700, 0xc42d3a4cc0, 0x2b, 0x30, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/db.go:507 +0x1fd fp=0xc44cd70940 sp=0xc44cd70820 pc=0xc818fd
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger.(*Item).yieldItemValue(0xc4204202c0, 0xc42d3a4c30, 0x2b, 0x30, 0x2, 0x0, 0xc42d392c23)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/iterator.go:169 +0x414 fp=0xc44cd70aa8 sp=0xc44cd70940 pc=0xc86f94
github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger.(*Item).yieldItemValue(0xc4204202c0, 0xc42d3a4ba0, 0x2b, 0x30, 0x2, 0x0, 0xc42d392c03)
        /home/stef/skewer-gopath/src/github.com/stephane-martin/skewer/vendor/github.com/dgraph-io/badger/iterator.go:178 +0x4d2 fp=0xc44cd70c10 sp=0xc44cd70aa8 pc=0xc87052

And so on afterward. The calls to yieldItemValue stack until explosion.

[stephane-martin]

Trivially replacing the recursive call in yieldItemValue by a for loop seems to solve the problem.

[manishrjain]

Did you write the same key over and over again? Can you narrow it down to a Go main program to illustrate the steps one can take to reach this state?

[stephane-martin]

@manishrjain : no it was different keys and values each time. But truely that was not an "infinite recursion". Just the stack was overwhelmed by some many recursive calls. After pushing the stack size with debug.SetMaxStack to an insane level, the program terminated (consuming roughly 6GB of RAM). All of that is gone after eliminating the recursive call in https://github.com/dgraph-io/badger/pull/497.

Incidently, I've discovered that the current Go compiler does not have a tail call optimization. So recursive function calls always push a frame on the stack. Ouch. (See discussion https://github.com/golang/go/issues/22624)

[romansemko]

Had the same issue over the couple few days: written over 20M key-value pairs. Deleted a bunch of them. The recursion then happens on a Get method for specific keys. Always. Not all keys are affected. Only a few "landmines" trigger the infinite loop.

I can try narrowing down to a simple go program, but cannot promise. Will also try older badger release, since I updated a few days ago.

[manishrjain]

If you can write up a program, where it triggers once in a while, I can run it in a loop on my machine and verify. Otherwise, I'll try and see if I can reproduce this on my own, over the next couple of weeks.

[manishrjain]

So, based on my rough testing, yieldItemValue is never called more than once during recursion. Which then makes me wonder, what is causing your recursion stack to get cooked? I'm not sure.

I wrote this program:

package main

import (
    "fmt"
    "log"
    "math/rand"
    "net/http"
    "sync"
    "time"

    "github.com/dgraph-io/badger"
    "github.com/dgraph-io/badger/options"
    "github.com/dgraph-io/badger/y"
    "github.com/dgraph-io/dgo/x"
)

func main() {
    fmt.Println("vim-go")
    dir := "/home/mrjn/badgertest"

    opts := badger.DefaultOptions
    opts.Dir = dir
    opts.ValueDir = dir
    opts.TableLoadingMode = options.MemoryMap
    opts.ValueLogLoadingMode = options.FileIO
    // opts.ValueLogFileSize = 64 << 20 // 64 MB.
    opts.SyncWrites = false

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

    go func() {
        if err := http.ListenAndServe("localhost:8081", nil); err != nil {
            log.Fatal(err)
        }
    }()

    closer := y.NewCloser(1)
    go func() {
        // Run value log GC.
        defer closer.Done()
        var count int
        ticker := time.NewTicker(30 * time.Second)
        defer ticker.Stop()
        for range ticker.C {
            select {
            case <-closer.HasBeenClosed():
                log.Printf("Num times value log GC was successful: %d\n", count)
                return
            default:
            }
            log.Printf("Starting a value log GC")
            err := db.RunValueLogGC(0.1)
            log.Printf("Result of value log GC: %v\n", err)
            if err == nil {
                count++
            }
        }
    }()

    var wg sync.WaitGroup
    for i := 0; i < 10; i++ {
        wg.Add(1)
        go func() {
            defer wg.Done()
            val := make([]byte, 64)
            rand.Read(val)
            for j := 0; j < 1e6; j++ {
                key := make([]byte, 16)
                _, err := rand.Read(key)
                x.Check(err)

                err = db.Update(func(txn *badger.Txn) error {
                    return txn.Set(key, val)
                })
                x.Check(err)
            }
        }()
    }

    wg.Wait()
    fmt.Println("Writes are done")

    wtxn := db.NewTransaction(true)
    var count int

    err = db.View(func(txn *badger.Txn) error {
        opts := badger.DefaultIteratorOptions
        opts.PrefetchValues = false
        itr := txn.NewIterator(opts)
        defer itr.Close()

        for itr.Rewind(); itr.Valid(); itr.Next() {
            item := itr.Item()
            key := item.KeyCopy(nil)
            x.Check(wtxn.Delete(key))
            count++
            if count > 1000 {
                x.Check(wtxn.Commit(nil))
                wtxn = db.NewTransaction(true)
                count = 0
            }
        }
        return nil
    })
    x.Check(err)
    if count > 0 {
        x.Check(wtxn.Commit(nil))
        count = 0
    }
    fmt.Println("Deletes are done")

    err = db.View(func(txn *badger.Txn) error {
        opts := badger.DefaultIteratorOptions
        itr := txn.NewIterator(opts)
        defer itr.Close()

        for itr.Rewind(); itr.Valid(); itr.Next() {
            item := itr.Item()
            val, err := item.Value()
            x.Check(err)
            if len(val) != 64 {
                log.Fatalf("Length of value must be 64. Key: %x", item.Key())
            }
        }
        return nil
    })
    x.Check(err)
    fmt.Println("Iteration is done")

    closer.SignalAndWait()
}

Still can't reproduce any bugs which cause an OOM.

[schomatis]

The moved item that is searched for (appending the !badger!move prefix) with the recursive call doesn't get its key updated, so new calls to yieldItemValue still look for the original key (instead of the moved key with the prefix). First generation moves will be found but further ones will not have the second move prefix added and it will keep looking for the first moved key in a infinite recursion.

[manishrjain]

That's an incorrect understanding.

yieldItemValue is called after having done the lookup for the key in the LSM tree. That lookup returns a value pointer. The task of yieldItemValue is exactly to use that value pointer to look into the value log and retrieve that value.

You can look here: https://github.com/dgraph-io/badger/blob/744717d82b6d465963bf8cb6690fdeb8e176dfc9/iterator.go#L158 to see that we're using item.vptr to do a read into the value log.

If that returns with an ErrRetry, we then do an LSM tree lookup for the move key, and retrieve its value pointer, if any. We set the item.vptr to that value, and call yieldItemValue again.

https://github.com/dgraph-io/badger/blob/744717d82b6d465963bf8cb6690fdeb8e176dfc9/iterator.go#L169

The logic looks sound to me.

P.S. There are no "second" generation move keys. If a key is moved twice, the move key is overwritten with the new value pointer.

[schomatis]

P.S. There are no "second" generation move keys. If a key is moved twice, the move key is overwritten with the new value pointer.

go run main.go
# Key found: !badger!moveKey: 1
# Key found: !badger!move!badger!moveKey: 1
# Key NOT found: !badger!move!badger!move!badger!moveKey: 1
# Key NOT found: Key: 2
# Key NOT found: !badger!moveKey: 2

main.go

package main

import (
    "log"
    "fmt"

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

func main() {
    // Open the Badger database located in the /tmp/badger directory.
    // It will be created if it doesn't exist.
    opts := badger.DefaultOptions
    opts.Dir = "/tmp/badger"
    opts.ValueDir = "/tmp/badger"
    opts.ValueLogFileSize = 15 << 20

    var entries int
    entries = 40

    var db *badger.DB

    for repeat := 0; repeat < 2; repeat++ {

        db = ReopenDB(nil, opts)

        // Insert keys.
        for i := 1; i < entries ; i++ {

            if i == 1 && repeat > 0 {
                continue
                // Only insert the 1st key once, it won't get deleted next,
                // just moved, so don't overwrite it.
            }

            err := db.Update(func(txn *badger.Txn) error {
                return txn.Set([]byte(fmt.Sprintf("Key: %d", i)), make([]byte, 1 << 20))
            })
            DontFail(err)
        }

        db = ReopenDB(db, opts)

        // Do not delete the first key so it gets moved.
        for i := 2; i < entries ; i++ {
            err := db.Update(func(txn *badger.Txn) error {
                return txn.Delete([]byte(fmt.Sprintf("Key: %d", i)))
            })
            DontFail(err)
        }

        db = ReopenDB(db, opts)

        // Run GC many times to ensure all files are GC'ed.
        for i := 0 ; i < 10; i++ {
            db.RunValueLogGC(0.1)
        }

        db.Close()
        db = nil
    }

    db = ReopenDB(db, opts)

    //LookForKey(db, "Key: 1")                            // fatal error: stack overflow
    LookForKey(db, "!badger!moveKey: 1")
    LookForKey(db, "!badger!move!badger!moveKey: 1")
    LookForKey(db, "!badger!move!badger!move!badger!moveKey: 1")
    LookForKey(db, "Key: 2")
    LookForKey(db, "!badger!moveKey: 2")

    db.Close()
}

// Reopen DB to force flushing entries to disk.
func ReopenDB(db *badger.DB, opts badger.Options) *badger.DB {
    if db != nil {
        err := db.Close()
        DontFail(err)
    }

    db, err := badger.Open(opts)
    DontFail(err)

    return db
}

func LookForKey(db *badger.DB, key string) {
    err := db.View(func(txn *badger.Txn) error {
        item, err := txn.Get([]byte(key))
        if err != nil {
            return err
        }

        _, err = item.Value()
        return err
    })

    if err == nil {
        fmt.Printf("Key found: %s\n", key)
        return
    }

    if err == badger.ErrKeyNotFound {
        fmt.Printf("Key NOT found: %s\n", key)
        return
    }

    DontFail(err)
}

func DontFail(err error) {
    if err != nil {
        log.Fatal(err)
    }
}

[manishrjain]

Thanks for that. I see the bug!

[manishrjain]

Submitted: https://github.com/dgraph-io/badger/commit/2e3a32f0ccac3066fb4206b28deb39c210c5266f

Can you try again at your end too, @schomatis ?

[manishrjain]

Can't spend too much time on this, but I just can't reproduce this at my end.

@stephane-martin , @romansemko : I'll leave it to you guys to create a reproducible example. I'll leave the issue around for a bit.

[schomatis]

Can you try again at your end too, @schomatis ?

This should be tested by @stephane-martin and @romansemko who had actual production scenarios impacted by this bug, if you already tried the script provided above there's not much more value I can add here.

That's an incorrect understanding.

@manishrjain Respectfully, let me use this issue as a great example of the importance of documentation in the design and implementation of a product. There was a massive GC modification (https://github.com/dgraph-io/badger/pull/479) with only some high-level explanation at the PR level and a few scarce comments at the code level (and none at the commit level), at least in my opinion, this is subjective of course, and I understand that documenting is far from an easy task (which can be even more time consuming than coding itself).

The more clear the product documentation is, the easier it's made for the community to contribute to it and the bigger it grows. Debugging this problem was a rather time-consuming task (which I'm happy to do because I want to improve Badger as much as possible to avoid OOM situations like the one described here), one needs to read the code line by line trying to reverse engineer design decisions like the one discussed above: from my (uninformed) perspective moved keys could be unlimitedly prefixed by that token, which isn't in itself a bug (bug or feature is just a question of intent) as long as it was part of the design of the solution, but if that design isn't available one has to make many judgement calls trying to pursue which part of the code is acting the way it should and which one isn't.

This is just a suggestion but please take this as an opportunity to look for ways to make Badger more open to the community to contribute to it, we're here to help :)

[manishrjain]

@schomatis : Please keep your comments short and precise. I'm not sure what you're suggesting.

[stephane-martin]

@manishrjain : better documentation for design decisions, so that we better understand the code and contribute to debugging more efficiently. I'll try the fix tomorrow, thanks for the good work.

[schomatis]

@manishrjain Sorry if I didn't explained myself more clearly, tl;dr, more comments in the code could make it easier to spot bugs like this one.

[manishrjain]

@stephane-martin : That is not a fix for the actual issue that you mentioned (and what this issue is about). The commit was purely for the bug that @schomatis brought up.

@schomatis : If you feel documentation is lacking, please send some PRs. Documentation is a shared responsibility.

[schomatis]

Documentation is a shared responsibility.

@manishrjain I totally agree, but keep in mind that the author of the PR (in this case you but could be anyone) is the one who actually knows why he is writing the code he is going to commit, the rest we can just guess.

Of course if I can contribute some documentation I will, but the author of what's being commited is in a unique position to write that documentation in the first place (which of course the rest can then review and add value to it, but first it is necessary for the author to get the ball rolling with some explanation of what he's doing).

[stephane-martin]

@manishrjain

• the main.go by @schomatis looks like the minimal test case that you wanted. So I don't exactly get it when you say "The commit was purely for the bug that schomatis brought up".
• after applying your fix on the master branch I can't reproduce the infinite loop in my program.

[manishrjain]

There were two things going on:

1. When moving a key during GC, the move prefix was being applied, even to the keys which were previously moved, and therefore already had the move prefix. That is, the move prefix was being applied repeatedly. That's the bug shown by the @schomatis 's main program, which I fixed.

2. When looking for a key, there seems to be some edge case which is causing infinite recursion, as the title of this issue states. That is a tangential issue, which is yet to be deterministically reproduced.

The first issue was fixed by my commit. The reasons for the second issue are still to be understood.

I doubt fix for 1 would affect the other. If you're unable to reproduce the second, that might just be due to the rare occurrence of this bug.

[manishrjain]

This should be fixed by https://github.com/dgraph-io/badger/pull/503.