Suspected memory leak in JSON decoder

[Misha Zatsman]

Hi,

I first noticed weird memory behavior with the JSON decoder in go 1.2.2, and I've seen it in 1.3.3 and 1.4. But maybe I'm just using the library incorrectly.

It seems like the JSON decoder is holding references to memory in two ways:

1) The reader that I pass into the decoder is not being garbage collected, leading me to assume that the decoder is keeping a pointer to it.

2) The buffer underlying the decoder is not being garbage collected, leading me to assume that the decoder is keeping a pointer to it.

Finally since both of the above are happening, that makes me think that something is keeping a reference to each decoder. I know I'm not!

I wrote code to demonstrate this behavior here:

https://play.golang.org/p/Q7aqLH4zpB

(It runs too long and gets killed in the sandbox, you have to copy it to your own machine and run it there)

The decoder is only used in this function:

// Generates a JSON string with a field of length textLen and then decodes it.

func DecodeJson(textLen int) {

var m Message

dec := json.NewDecoder(generateJson(textLen))

if err := dec.Decode(&m); err != nil {

log.Fatal(err)

}

}

So I assume the decoder and the buffer and reader that it uses would be garbage collected, but they don't seem to be.

Even though the largest JSON field I pass to the decoder is 2**28 (268 MB), the memory usage according to the heap profiler is over 155 GB!

Thanks in advance for any help!

All my code was run using go 1.4 Here's what looked interesting to me from the profiler:

go tool pprof -text leak json.heap.profile 

155.60GB of 311.36GB total (49.98%)

Dropped 16 nodes (cum <= 1.56GB)

      flat  flat%   sum%        cum   cum%

   92.98GB 29.86% 29.86%    92.98GB 29.86%  encoding/json.(*Decoder).readValue

   62.63GB 20.11% 49.98%    62.63GB 20.11%  main.generateJson

         0     0% 49.98%    92.98GB 29.86%  encoding/json.(*Decoder).Decode

         0     0% 49.98%   155.60GB 49.98%  main.DecodeJson

         0     0% 49.98%   155.60GB 49.98%  main.main

         0     0% 49.98%   155.60GB 49.98%  runtime.goexit

         0     0% 49.98%   155.60GB 49.98%  runtime.main

(pprof) list readValue

Total: 311.36GB

ROUTINE ======================== encoding/json.(*Decoder).readValue in /usr/local/go/src/encoding/json/stream.go

   92.98GB    92.98GB (flat, cum) 29.86% of Total

         .          .    112:           }

         .          .    113:

         .          .    114:           // Make room to read more into the buffer.

         .          .    115:           const minRead = 512

         .          .    116:           if cap(dec.buf)-len(dec.buf) < minRead {

   92.98GB    92.98GB    117:                   newBuf := make([]byte, len(dec.buf), 2*cap(dec.buf)+minRead)

         .          .    118:                   copy(newBuf, dec.buf)

         .          .    119:                   dec.buf = newBuf

         .          .    120:           }

         .          .    121:

         .          .    122:           // Read.  Delay error for next iteration (after scan).

(pprof) list generateJson

Total: 311.36GB

ROUTINE ======================== main.generateJson in /home/mishaz/arvados/services/datamanager/leak.go

   62.63GB    62.63GB (flat, cum) 20.11% of Total

         .          .     51:           "num-iter",

         .          .     52:           10,

         .          .     53:           "The number of times we'll loop through all the text lengths.")

         .          .     54:}

         .          .     55:

   62.63GB    62.63GB     56:

         .          .     57:// Returns a Reader containing a JSON structure with 2 fields, the

         .          .     58:// second of which has a field of length textLen.

         .          .     59:func generateJson(textLen int) io.Reader {

         .          .     60:   totalLength := JsonPrefixLen + textLen + JsonSuffixLen

         .          .     61:   suffixStart := totalLength - JsonSuffixLen

         .          .     62:   buf := make([]byte, totalLength)

         .          .     63:

         .          .     64:   fill := buf[JsonPrefixLen:suffixStart]

         .          .     65:   copy(fill, Filler)

         .          .     66:   for copied := FillerLen; copied < textLen; copied *= 2 {

         .          .     67:           copy(fill[copied:], fill[:copied])

         .          .     68:   }

         .          .     69:

         .          .     70:   copy(buf, JsonPrefix)

         .          .     71:   copy(buf[totalLength-JsonSuffixLen:], JsonSuffix)

         .          .     72:

[Dave Cheney]

Thanks for your repro.

I can't reproduce your findings. The memory usage for your sample stabalises at 2.197g RSS on my machine according to top(1). This matches the output of GODEBUG=gctrace=1 which shows heap size growing to 2048mb.

If I modify your example to pause after the last iteration I can see the scavenger release 100% of the heap.

2014/12/31 17:13:46 Decoding Json with text length 67108864

2014/12/31 17:13:47 Decoding Json with text length 134217728

gc137(1): 125+0+77+0 us, 1024 -> 2048 MB, 546 (5940-5394) objects, 4 goroutines, 219/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc138(1): 362+0+108+0 us, 2048 -> 2048 MB, 546 (5940-5394) objects, 4 goroutines, 219/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc139(1): 135+0+63+0 us, 224 -> 608 MB, 110 (5942-5832) objects, 4 goroutines, 219/41/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc140(1): 338+0+104+0 us, 608 -> 608 MB, 110 (5942-5832) objects, 4 goroutines, 219/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

2014/12/31 17:13:49 Decoding Json with text length 268435456

gc141(1): 124+0+73+0 us, 512 -> 1152 MB, 136 (5979-5843) objects, 4 goroutines, 219/25/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc142(1): 342+0+107+0 us, 1152 -> 1152 MB, 136 (5979-5843) objects, 4 goroutines, 219/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc143(1): 122+0+59+0 us, 448 -> 1216 MB, 110 (5981-5871) objects, 4 goroutines, 219/37/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc144(1): 340+0+108+0 us, 1216 -> 1216 MB, 110 (5981-5871) objects, 4 goroutines, 219/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

scvg0: inuse: 1280, idle: 834, sys: 2114, released: 0, consumed: 2114 (MB)

GC forced

gc145(1): 12+7+504+3 us, 1024 -> 1280 MB, 112 (5992-5880) objects, 5 goroutines, 219/25/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc146(1): 688+1+398+2 us, 1280 -> 1280 MB, 112 (5992-5880) objects, 5 goroutines, 219/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

scvg1: inuse: 0, idle: 2114, sys: 2114, released: 0, consumed: 2114 (MB)

GC forced

gc147(1): 11+7+434+1 us, 0 -> 0 MB, 101 (5992-5891) objects, 5 goroutines, 219/25/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

gc148(1): 623+2+387+1 us, 0 -> 0 MB, 101 (5992-5891) objects, 5 goroutines, 219/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields

I am not 100% sure, but the 'leak' you see may be coming from heap profiling itself; the profile data has to go somewhere.

Dave

[Misha Zatsman]

Thanks Dave!

You're absolutely right. When I look in top my memory usage doesn't go much above 2GB and I get similar results to yours when I use GODEBUG=gctrace=1 (didn't know about that debug switch, thanks!)

So my next question is what am I doing wrong to get such inflated numbers from pprof?

I started down this path because my real life json decoding (of long strings) was running out of memory and I was trying to find where all the memory was going. I started using pprof and found alarming results, prompting me to post here.

It seems like I've misunderstood how to use pprof for heap profiling. Should I not be calling WriteHeapProfile() more than once within an execution?

Is there a better way to debug out of memory errors?

[Dave Cheney]

Personally I've never found the heap profiler to be very useful. Cab you post the error message you get and some source code?

[minux]

On Wed, Dec 31, 2014 at 1:14 PM, Misha Zatsman <mis...@gmail.com> wrote:

So my next question is what am I doing wrong to get such inflated numbers from pprof?

I started down this path because my real life json decoding (of long strings) was running out of memory and I was trying to find where all the memory was going. I started using pprof and found alarming results, prompting me to post here.

It seems like I've misunderstood how to use pprof for heap profiling. Should I not be calling WriteHeapProfile() more than once within an execution?

Please note that profiles written to the same output file are accumulative, so

for example, if you call WriteHeapProfile() ten times at the same place in a row,

you will get ~10x the actual heap usage.

[Misha Zatsman]

Thanks Minux!

I updated my code to overwrite the file, so it contains at most one heap profile and that fixed my problem:

https://play.golang.org/p/nPyylj8jBs

This will work for code that crashes with out of memory (unless of course it crashes while recording the heap profile)