memory leak in crypto/merkle (?)

[ebuchman]

Running a default single node causes the memory to grow.

Inspecting the difference in heap dumps as the memory grows suggests there's a leak in the use of the Merkle tree.

Running a very simple test confirms this.

For instance this code:

package main

import (
	"fmt"
	"net/http"
	_ "net/http/pprof"
	"runtime"

	"github.com/tendermint/tendermint/crypto/merkle"
)

func main() {
	runtime.MemProfileRate = 1
	fmt.Println("vim-go")
	list := [][]byte{
		[]byte("hello"),
		[]byte("goodbye"),
		[]byte("ok"),
	}
	myFunc(list)
	runtime.GC()
	http.ListenAndServe("localhost:7070", nil)
	fmt.Println(list)
}

func myFunc(list [][]byte) {
	merkle.SimpleHashFromByteSlices(list)
}

Leaves many of these such entries in the heap profile:

0: 0 [1: 80] @ 0x1408c93 0x140c888 0x140ceff 0x140cda2 0x102f167 0x105d5a1
#	0x1408c92	github.com/tendermint/tendermint/crypto/merkle.innerHash+0x162			/Users/ethanbuchman/programming/goApps/src/github.com/tendermint/tendermint/crypto/merkle/hash.go:20
#	0x140c887	github.com/tendermint/tendermint/crypto/merkle.SimpleHashFromByteSlices+0x137	/Users/ethanbuchman/programming/goApps/src/github.com/tendermint/tendermint/crypto/merkle/simple_tree.go:19
#	0x140cefe	main.myFunc+0x3e								/Users/ethanbuchman/programming/goApps/src/github.com/tendermint/tendermint/pprof/main.go:27
#	0x140cda1	main.main+0x1f1									/Users/ethanbuchman/programming/goApps/src/github.com/tendermint/tendermint/pprof/main.go:20
#	0x102f166	runtime.main+0x206								/Users/ethanbuchman/goRoot/1.11.5/src/runtime/proc.go:201

[ebuchman]

Best I can tell this is a memory leak in sha256 in the stdlib, which is kind of hard to believe, so maybe someone can help sanity check this. But the following code seems to leak:

package main

import (
	"crypto/sha256"
	"fmt"
	"net/http"
	_ "net/http/pprof"
	"runtime"
)

func main() {
	runtime.MemProfileRate = 1
	myFunc()
	runtime.GC()
	fmt.Println(http.ListenAndServe("localhost:7070", nil))
}

func myFunc() {
	sha256.New()
}

with

0: 0 [1: 128] @ 0x107563d 0x1300102 0x1300061 0x102ee57 0x105ca71
#	0x107563c	crypto/sha256.New+0x2c	/Users/myuser/goRoot/1.11.5/src/crypto/sha256/sha256.go:181
#	0x1300101	main.myFunc+0x21	/Users/myuser/goApps/src/github.com/tendermint/tendermint/pprof/main.go:19
#	0x1300060	main.main+0x30		/Users/myuser/goApps/src/github.com/tendermint/tendermint/pprof/main.go:13
#	0x102ee56	runtime.main+0x206	/Users/myuser/goRoot/1.11.5/src/runtime/proc.go:201

The leak is also there if we use sha512, but not if we use sha1 or ripemd160. It's hard to understand this, since by looking at the code, sha256 and sha1 do almost exactly the same thing in the New function ...

[odeke-em]

Hello @ebuchman, please try this simplified reproducer which just uses runtime.MemStats, replacing sha256.New() with the other algorithms

package main

import (
	"crypto/sha256"
	"runtime"
)

var sink string

func main() {
	var before, after uint64
	sink = "foo"
	runtime.MemProfileRate = 1
        ms := new(runtime.MemStats)
	runtime.GC()
	runtime.ReadMemStats(ms)
	before = ms.Alloc
	println("Before:     ", before)

	myFunc()
	runtime.GC()

	runtime.ReadMemStats(ms)
	after = ms.Alloc
	println("After:      ", after)
	println("Difference: ", after-before)
}

func myFunc() {
	sha256.New()
	if sink != "foo" {
		panic("Just here to ensure code isn't optimized away")
	}
}

and running

for ((i=0; i < 10; i++)) do echo -e "Run #$i\r" && go run ts.go && echo -e "\n" ;done

On my computer, it gives

Run #0
Before:      102168
After:       102168
Difference:  0


Run #1
Before:      102168
After:       104056
Difference:  1888


Run #2
Before:      100280
After:       102168
Difference:  1888


Run #3
Before:      102168
After:       102168
Difference:  0


Run #4
Before:      102168
After:       102168
Difference:  0


Run #5
Before:      100280
After:       100280
Difference:  0


Run #6
Before:      102168
After:       102168
Difference:  0


Run #7
Before:      102264
After:       102264
Difference:  0


Run #8
Before:      100280
After:       100280
Difference:  0


Run #9
Before:      102168
After:       102168
Difference:  0

[odeke-em]

For a deeper analysis, we might want to instead perform an experiment by turning off GC and seeing how many bytes are allocated by sha256.New and then afterwards trying to correlate those values with those that pprof shows.

How did you come to this conclusion about sha256? Did you extract this code from a server?

[odeke-em]

@ebuchman in your repro in there is a little tricky thing that might explain your problem

Notice that you've got

func main() {
	runtime.MemProfileRate = 1
	fmt.Println("vim-go")
	list := [][]byte{
		[]byte("hello"),
		[]byte("goodbye"),
		[]byte("ok"),
	}
	myFunc(list)
	runtime.GC()
	http.ListenAndServe("localhost:7070", nil)
	fmt.Println(list) <---- Notice this?
}

http.ListenAndServe blocks till we hit Ctrl-C, but you are retaining a reference here so list
won't get garbage collected throughout the lifetime of the program. Please correct that and retry your repro.

[liamsi]

Exactly, I slightly changed the example to the following:

func main() {
	runtime.MemProfileRate = 1
	go func() {
		http.ListenAndServe("localhost:7070", nil)
	}()
	otherFunc()
	// runtime.GC()
	runtime.GC()
	fmt.Println("ok ...")

	//time.Sleep(20*time.Second)
	//fmt.Println("ok2 ...")
	time.Sleep(120*time.Second) // <- this is only so I have plenty of time to see what is going on
}

func otherFunc() {
	size := 100000
	list := make([][]byte, size)

	for i:=0; i<size; i++ {
		list[i] = []byte("hello"+string(i))
	}

	myFunc(list)
	fmt.Println("done my func")
	//time.Sleep(time.Second*10)
}

func myFunc(list [][]byte) {
	merkle.SimpleHashFromByteSlices(list)
}

using go tool pprof -png http://localhost:7070/debug/pprof/heap > out.png after I see
ok ..., does show there is nothing left on the heap. Same, if we give the GC enough time to kick in itself (even without explicitly calling it).

[jessysaurusrex]

Wasn't able to reproduce this as Alloc is 0 after GC. https://gist.github.com/jessysaurusrex/8d73c3df00c0a813d7aef4cb66eafe3d#file-sha256demo-go

[ebuchman]

How did you come to this conclusion about sha256? Did you extract this code from a server?

I was trying to debug what seemed like a mem leak in tendermint and sanity checking my understanding of the memory profiler led me to discover that sha256.New() seems to persist in the heap profiler.

in your repro in there is a little tricky thing that might explain your problem

See the second comment which is even simpler and doesn't use the list and yet the result of sha256.New() still shows in the heap profiler. Maybe a problem with the heap profiler?

[ebuchman]

Bumping this from milestone as seemingly non-critical, but should probably still be investigated

[brapse]

As a follow up to [#3530] I also tried to reproduce a memory leak in sha256.New(), merkle.SimpleHashFromByteSlices and the new merkle.SimpleHashFromByteSlicesIterative but was unable to reproduce leaks in any of them. Just commenting here for additional evidence.

package main

import (
    "crypto/sha256"
    "net/http"
    _ "net/http/pprof"
    "runtime"
    "time"

    "github.com/tendermint/tendermint/crypto/merkle"
)

func main() {
    go func() {
        http.ListenAndServe("localhost:7070", nil)
    }()
    var before, after uint64
    runtime.MemProfileRate = 1
    ms := new(runtime.MemStats)

    runtime.GC()
    runtime.ReadMemStats(ms)
    before = ms.Alloc

    size := 100000
    list := make([][]byte, size)

    for i := 0; i < size; i++ {
        list[i] = []byte("hello" + string(i))
    }
    println("Before:     ", before)

    hashRecursive(list)
    runtime.GC()

    runtime.ReadMemStats(ms)
    after = ms.Alloc
    println("After:      ", after)
    println("Difference: ", int64(after)-int64(before))
    time.Sleep(120 * time.Second)
}

func myFunc() {
    sha256.New()
}

func hashRecursive(list [][]byte) {
    merkle.SimpleHashFromByteSlices(list)
}

func hashIterative(list [][]byte) {
    merkle.SimpleHashFromByteSlicesIterative(list)
}

[dshulyak]

i can try to explain why there was an impression that sha256 leaks. first 4 values in each heap profile record are inuse objects: inuse space, [alloc objects: alloc space], this line 0: 0 [1: 128] @ 0x107563d 0x1300102 0x1300061 0x102ee57 0x105ca71 says that 128 bytes escaped to heap, but no other object holds references to them.

take a look at the following example: (btw you need to ensure that function returns interface and it is used somehow, otherwise compiler will inline those calls down to new(sha1.digest) and new(sha256.digest) and they will be stack allocated, can be checked with gcflags=-m. maybe it wasn't the case with go1.11).

package main

import (
	"crypto/sha1"
	"crypto/sha256"
	"fmt"
	"hash"
	"net/http"
	_ "net/http/pprof"
	"runtime"
)

func main() {
	runtime.MemProfileRate = 1
	fmt.Println(s1().Size())
	runtime.GC()
	h := s2()
	defer func() {
		fmt.Println(h.Size())
	}()
	runtime.GC()
	fmt.Println(http.ListenAndServe("localhost:7070", nil))
}

func s1() hash.Hash {
	return sha1.New()
}

func s2() hash.Hash {
	return sha256.New()
}

both values will be visible in heap profile, but sha256 version is referenced in defer and won't be released in this program (note the difference in inuse values):

0: 0 [1: 112] @ 0x74e88b 0x74e87b 0x74e8bb 0x4321ce 0x45f751
#	0x74e88a	crypto/sha1.New+0x4a	/home/dd/.go/src/crypto/sha1/sha1.go:122
#	0x74e87a	main.s1+0x3a		/home/dd/tests/profsha/main.go:26
#	0x74e8ba	main.main+0x7a		/home/dd/tests/profsha/main.go:15
#	0x4321cd	runtime.main+0x21d	/home/dd/.go/src/runtime/proc.go:203

1: 128 [1: 128] @ 0x74e953 0x74e943 0x74e942 0x4321ce 0x45f751
#	0x74e952	crypto/sha256.New+0x112	/home/dd/.go/src/crypto/sha256/sha256.go:162
#	0x74e942	main.s2+0x102		/home/dd/tests/profsha/main.go:30
#	0x74e941	main.main+0x101		/home/dd/tests/profsha/main.go:17
#	0x4321cd	runtime.main+0x21d	/home/dd/.go/src/runtime/proc.go:203

[egonspace]

Has this problem been resolved? Is it related to this(golang/go#42347)?

[tac0turtle]

closing as many people were not able to reproduce, and we optimized the merkle hashing recently