Possible snappy/s2 memory leak

[joe-elliott]

I unfortunately am unable to provide exact details or a minimally reproducible code sample, but we are seeing a memory leak when we swapped from github.com/golang/snappy to github.com/klauspost/compress/snappy. The latter definitely performed better and we were excited to try the s2 compression as well, but we will have to revert for now.

Here is the change but I don't expect you to dig through this code. It's difficult for someone unfamiliar with our codebase to track down the exact code path that makes use of compression. As far as I can tell we are correctly calling .Close() on the writer and allowing the reader to fall out of scope.

Here is our latest attempt to use snappy. In this PR we removed all attempts to pool the reader/writer and always allocate New, but it still exhibits the leak. This mirrors how we use your zstd encoder/decoder where we do not see this issue.

Thank you for this compression library and I apologize for this vague issue, but I wanted to pass on what we were seeing. If I have time I will attempt to repro with a minimal sample and will pass along any updates.

FWIW we are using snappy for our WAL on incoming data and compressing about 5MB/s. We are seeing a leak of ~300MB/hour.

[klauspost]

@joe-elliott Do you have an memory pprof that shows what is being leaked?

Calling Close twice shouldn't hurt, so forcefully closing before returning the Writer could help in case you don't always get it called.

[joe-elliott]

I've spent some time tracking down codepaths and I believe that we are always correctly calling .Close() on the writer. However, it is complex due to the way we are trying to pool the writer/readers and I admit there may be a gap in my analysis. I do know that github.com/golang/snappy is not showing this same leak, but perhaps it does not rely on .Close() being called to cleanup all allocations?

This is after ~6.5 hours of run time:
klauspost-snappy.zip

And the same image after ~5 mins of run time:
klauspost-5mins.zip

The large tempopb.glob..func1 is expected as we basically pool as much of our byte slice allocations through it when marshalling proto.

[joe-elliott]

Also, running a goroutine profile and seeing 157 encoder goroutines.

----------------------------------------------------------+-------------
         0     0%   100%        157 34.51%                | github.com/klauspost/compress/s2.(*Writer).Reset.func1 /home/joe/dev/joe-elliott/tempo/vendor/github.com/klauspost/compress/s2/encode.go:475
                                               157   100% |   runtime.chanrecv2 /usr/local/go/src/runtime/chan.go:444
----------------------------------------------------------+-------------

Blocked on this line:

   for write := range toWrite {

So either we are not calling Close 100% of the time or there is some sequence of calls that can orphan this goroutine.

The calling order for the provided profiles was:

b := &bytes.Buffer{}
w := snappy.NewBufferedWriter(b)
for a bunch of times
    w.Write()
    w.Close()
    b.Reset()
    w.Reset(b)
w.Close()

[klauspost]

@joe-elliott That is why you IMO should just call Close before putting it back into the pool.

This will also dereference the upsteam io.Writer so you don't keep that around for no reason.

[joe-elliott]

I found and fixed the issue in grafana/tempo#980. There was one codepath that resulted in an unclosed writer. I apologize for the noise!

Thank you for your work on this excellent compression library.