High memory usage when Enumerating

[tgulacsi]

Hi,

I'm using (kv.DB).Seek() and enum.Next() on the returned kv.Enumerator. During this I see high RSS - after finishing with the enumerator, pprof registered mem usage drops to 4Mb.

With the help of the attached pprof heap diagram, I've found in lldb/xact.go that ReadAt stored the read pages - for what? Why not leave this to the OS' page cache? Or use an LFU cache?

Thanks, Tamás Gulácsi

[cznic]

Hi Tamás,

xact.go provides transactional filers (think of just a normal disk file). This requires to implement commit and rollback. That requires to have a single byte precise information about modified parts of the file and have two versions of the file: the uncommitted file and a separate view of the same, but with the modifications applied - for so called "dirty" reads, which is a requirement of any transaction in progress when it needs to consistently "see" the changes it made to the file so far.

Implementing this is possible in many ways. One of them is using the classic concept of dirty pages (like OS kernel uses to manage RAM vs VA space).

To make the long story short: ReadAt caches the pages because the estimate is that often a page read is a prelude to subsequential modification of the same page. However, this is not true when enumeration of the kv tree, or some of its part is done.

The culprit is that kv tried to be very easy to use and thus does everything within a implicit (micro) transaction instead of requiring the user to be explicit about it - like eg. ql does. That means even R/O operations like enumerate now carry the weight of a transaction. OTOH, the transaction should be limited to the execution of .Next() only.

There are different possible approaches which might improve the situation:

• Do not cache not-yet dirty pages in lldb by (*bitFiler).ReadAt and postpone the caching to the moment when it is inevitable (on .WriteAt). It would impact positively smallish non dirty reads and negatively read/modify/writes. Having only synthetic benchmarks available it would not be easy to judge if the gains outweigh the losses.
• Do not perform .Next/.Prev in kv in an automatic transaction, perform those methods under a simple mutex lock of the whole DB. This might be feasible as those methods generally perform fast (O(1+fileAccess)) and actually the lock part is already there. It'd be only needed to drop the transaction part. Might also improve .Get performance as a bonus. The change would be to add a readOnly bool argument to (*DB).enter() and do not trigger the automaton state change, if not already in a transaction, when the value is true.
• Last but not least, the bitFiler doesn't recycle the pages to GCache, unlike most of the other lldb parts. It's because now it uses an array, but that can be changed to a slice probably easily.

Maybe even the combination of all of the above options is the right mix. I would appreciate to know your thoughts about it.

Do you perhaps feel like trying to experiment with it by your own? If so, I'll provide any support required. Otherwise I can get into this on some weekend, but not this one - all amusement parks around are starting the season this weekend and my daughter was promised to be there ;-)

PS: Even though there are some benchmarks both in lldb and kv, maybe a best start is to write a new benchmark or few of them for this troubled case(s) to have a fixed point which the later modifications could be compared to. Would you maybe want to write it/them? The advantage would be that you're not biased - I might be subconsciously preferring using the easier/faster paths I know about in the code.

PS2: I cannot see the "attached pprof heap diagram" being actually attached...?

Accepted #SomeWeekend

[cznic]

Now I can see the SVG. Convincing, admitted. Is that a --inuse_space or --alloc_space graph? Can I have a repro case please? Thanks in advance.

[tgulacsi]

1. Don't hurry, this is not an actual, in-production problem. From your suggestions, I'd prefer the second and the third point - the first is too evasive. But maybe the benefits are low if we don't cut big enough :) Don't know, must benchmark.
2. the heap diagram is produced with " go tool pprof http://localhost:8181 web "
3. I'm trying to prepare an example db (these are logs...). But strange enough, my very simple obfuscating program (see below) does not suffer from the high memory usage. In my real program I use Seek and not SeekFirst, and I do some Get according to the value (I had to split the log record because of the value size limit).

This obfuscated db will be available at http://git.gthomas.eu/gthomas/kv-issue-20.kv.gz

kv-copy-shuffle.go: package main

import ( "flag" "fmt" "io" "log" "math/rand" "os"

    "github.com/cznic/kv"

)

func main() { flag.Parse() srcFn := flag.Arg(0) dstFn := flag.Arg(1)

    src, err := openKV(srcFn)
    ne(err)
    defer src.Close()
    dst, err := openKV(dstFn)
    ne(err)
    defer dst.Close()

    n := 0
    enum, err := src.SeekFirst()
    ne(err)
    for {
            k, v, err := enum.Next()
            if err == io.EOF {
                    break
            }
            ne(err)
            ne(dst.Set(k, shuffle(v)))
            n++
            if n%10000 == 0 {
                    log.Printf("%d", n)
            }
    }

}

func shuffle(b []byte) []byte { for i, j := range rand.Perm(len(b)) { b[i] = b[j] } return b }

func ne(e error) { if e != nil { log.Fatal(e) } }

func openKV(filename string) (*kv.DB, error) { createOpen := kv.Open verb := "opening" if _, err := os.Stat(filename); os.IsNotExist(err) { createOpen = kv.Create verb = "creating" } opts := &kv.Options{ VerifyDbBeforeOpen: true, VerifyDbAfterOpen: true, VerifyDbBeforeClose: true, VerifyDbAfterClose: true, } db, err := createOpen(filename, opts) log.Printf("db==%#v, err=%v", db, err) if err != nil { return nil, fmt.Errorf("error %s %s: %v", verb, filename, err) }

    if db == nil {
            return nil, fmt.Errorf("nil db!")
    }
    return db, nil

}

I'm enumerating on keys starting with '!' (after it a date comes - these are logs)

[cznic]

Tried options 1 and 3: Not good at all. Option 2 seems to improve things. Will push in a moment. Can you please update and try again?

[tgulacsi]

I don't see any advance memory-wise. Maybe we really need a proper test case... I'll try to build something on Monday.

[tgulacsi]

1. download http://git.gthomas.eu/gthomas/kv-issue-20.kvdb
2. git clone https://github.com/tgulacsi/log2db.git
3. cd log2db && go build && ./log2db -db=kv-issue-20.kvdb serve
4. curl http://localhost:8181/?after=0001-01-01T00%3A00%3A01Z&before=2014-04-12T16%3A14%3A27%2B02%3A00&limit=100&search=Search! >/dev/null
5. watch RSS go up, use go tool pprof http://localhost:8181

You can shorten start time by turning VerifyDb*Open options off at store/kv.go#66

[cznic]

1. Okay, no problems.
2. Ditto
3. Several unresolved dependencies. I thought, okay, I'll use go get instead, that'll take care of that. However, go get fails:

(11:02) jnml@r550:~/src/github.com/tgulacsi$ go get -x -v github.com/tgulacsi/log2db
github.com/tgulacsi/log2db (download)
cd .
git clone https://github.com/tgulacsi/log2db /home/jnml/src/github.com/tgulacsi/log2db
cd /home/jnml/src/github.com/tgulacsi/log2db
git show-ref
cd /home/jnml/src/github.com/tgulacsi/log2db
git checkout master
github.com/tgulacsi/go (download)
cd .
git clone https://github.com/tgulacsi/go /home/jnml/src/github.com/tgulacsi/go
cd /home/jnml/src/github.com/tgulacsi/go
git show-ref
cd /home/jnml/src/github.com/tgulacsi/go
git checkout master
Fetching https://unosoft.hu/log2db/parsers?go-get=1
https fetch failed. # after several minutes
...

go get then tries to make makes further progress from this point to no avail. Please advise.

In the mean time, I'll extend the existing benchmarks with a new enumerating one, parametrized by an existing DB and will report back the results.

[cznic]

I've moved the code to verify before close to be outside of a transaction. I think this fixed the issue. Please try the new version (push follows) and let me know. Thanks.

(12:08) jnml@r550:~/src/github.com/cznic/kv$ go test -c && ./kv.test -test.run NONE -test.bench Enum -test.memprofile mem.out -db ~/src/github.com/cznic/kv-issue-20.kvdb 
PASS
BenchmarkEnumerateDB           1    7976117871 ns/op
--- BENCH: BenchmarkEnumerateDB
    all_test.go:1949: 870619 keys using /home/jnml/src/github.com/cznic/kv-issue-20.kvdb
(12:09) jnml@r550:~/src/github.com/cznic/kv$ go tool pprof kv.test mem.out --web
Adjusting heap profiles for 1-in-524288 sampling rate
Dropping nodes with <= 0.0 MB; edges with <= 0.0 abs(MB)
Loading web page file:////tmp/SU8_YVquZj.0.svg
Ve stávající relaci prohlížeče bylo vytvořeno nové okno.
(12:09) jnml@r550:~/src/github.com/cznic/kv$ 

[tgulacsi]

Thank you!

This solves my problem perfectly. (And sorry about the "reproduction" steps: I've forgot to change the import paths from unosoft.hu/log2db to github.com/tgulacsi/log2db).

[cznic]

Glad we managed to resolve this! ;-)