fork/exec .. cannot allocate memory

[Petar Maymounkov]

I've written a blogging system in Go that displays posts stored in a
GIT repository.

The system has a subtle memory leak that shows up after 2 weeks of
online time usually.

The leak manifests itself in the following way. Every time the system
needs to
read the timestamp of a post, it runs the git command to get stats on
the respective posts.
After awhile of up-time, the attempt to run GIT, which is done using
exec.Run()
returns this error:

fork/exec /usr/bin/git: cannot allocate memory

The system is relatively simple (not a lot of code) and I have not
been able to find
a leaky place in the code.

Pprof dumps seem to suggest that most memory is allocated in
ioutil.ReadFile.
So I've looked carefully into whether I am freeing the file contents
after I serve it.
I am not really able to find a bug in the code.

I am wondering if there is something else I should be looking at,
given the specific error
that occurs at fork/exec.

Oh, and the code can be found here:

http://github.com/petar/Faff

Thanks,
--Petar

[Rob 'Commander' Pike]

You don't provide a profile, but from your description my guess is that you're holding on to a slice of the data returned by ReadFile so the whole file is being kept in memory.

-rob

[Petar Maymounkov]

And did some investigation, and while I could not find a leak in my code,
it lead me to test some of Go's memory behavior which lead to a confusing
outcome.

Consider the program:

package main

import (
"fmt"
"runtime"
"time"
"github.com/petar/GoGauge/pprof"
)

func getSomeMem() []byte { return make([]byte, 1e7) } // allocate 10MB

func main() {
pprof.StartLogging("pprof.log", 1e8) // This dumps PPROF is a
separate file every 1/10 sec
time.Sleep(5e9)
e := 0
for k := 0; k < 10000; k++ {
_ = getSomeMem()
if k % 10 == 0 {
fmt.Printf("Read: %d/%d \r", k, e)
}
}
runtime.GC()
time.Sleep(60e9)
}

This program has three stages.

In stage 1, it waits for 5 seconds (and does nothing else).
The pprof for this stage looks like this:

Total: 1.0 MB (this varies between 0.5 MB to 1.5MB)
1.0 100.0% 100.0% 1.0 100.0% __cgo_allocate
0.0 0.0% 100.0% 0.5 50.0% __cgo_panic

Stage 2 is the loop. Here pprof looks like this:

Total: 39.2 MB
39.2 100.0% 100.0% 39.2 100.0% __cgo_allocate
0.0 0.0% 100.0% 1.0 2.6% __cgo_panic

Stage 3 is after garbage collection has been run, and the program is
sleeping for 1 minute:

Total: 16.5 MB
16.5 100.0% 100.0% 16.5 100.0% __cgo_allocate
0.0 0.0% 100.0% 1.0 6.0% __cgo_panic

Why are there 16MB of allocated memory still?

If I run "top" on this program, the real size of this program is about 51MB
and it never drops (even after the loop ends and garbage collection happens).

Here's something even more confusing:

If I change the make([]byte, ...) allocation size from 10MB to
something higher or lower,
*all* numbers in the above dumps (as well as the "top" numbers) scale
accordingly.

This makes it look like: If I make a large slice and then delete it, I
will end up having
less real memory than if I made a small slice and then deleted it.

What is the explanation?

Thanks,
--Petar

[Kyle Lemons]

What is the explanation?

The Go garbage collector does not currently return memory to the OS, it keeps it around for future allocations.

--
~Kyle

"Everyone knows that debugging is twice as hard as writing a program in the first place. So if you're as clever as you can be when you write it, how will you ever debug it?" 
— Brian Kernighan

[Petar Maymounkov]

I see.

OK, I have a related question regarding PPROF dumps and their meaning.

I've obtained a PPROF dump of a web server which has been running
for a few days (and served thousands of requests), however at the
time the dump was taken (nothing was being served) and the memory utilization
should have been close to 0.

All the server does is serve static files by reading them from disk,
serving them and then forgetting their contents. So, if serving no requests,
you'd expect next to no memory in use.

The real memory used by the process is 200M (at quiet time). Let's assume
that this is because Go does not return memory to the OS and
perhaps 200M was utilized at some peak time.
The PPROF during quiet time is pasted below. My question is:

Does the PPROF dump account just for things that are currently
legitimately allocated blocks (GC thinks of them as in-use) or does
it account for all blocks allocated throughout the life of the process?

I ask because:

If PPROF only shows current in-use blocks, then the dump below would
imply that I have a memory leak. This is very unlikely because the code
is so simple that I have manually verified multiple times that it has no leaks.
On the other hand, if PPROF shows stats for blocks allocated over past
times as well, then this dump would be consistent with the fact that
Go does not return memory to the OS.

Total: 201.5 MB
201.5 100.0% 100.0% 201.5 100.0% runtime.mallocgc
0.0 0.0% 100.0% 0.5 0.2% allocsg
0.0 0.0% 100.0% 4.0 2.0% crosscall_amd64
0.0 0.0% 100.0% 1.5 0.7%
github%2ecom/petar/GoHTTP/http.*ServerConn·Read
0.0 0.0% 100.0% 188.0 93.3%
github%2ecom/petar/GoHTTP/http.NewBodyFile
0.0 0.0% 100.0% 188.0 93.3%
github%2ecom/petar/GoHTTP/http.NewResponseFile
0.0 0.0% 100.0% 0.5 0.2%
github%2ecom/petar/GoHTTP/http.ReadRequest
0.0 0.0% 100.0% 1.0 0.5% github%2ecom/petar/GoHTTP/http._func_001
0.0 0.0% 100.0% 2.5 1.2%
github%2ecom/petar/GoHTTP/server.*Query·ContinueAndWrite
0.0 0.0% 100.0% 2.5 1.2%
github%2ecom/petar/GoHTTP/server.*Query·Write
0.0 0.0% 100.0% 193.5 96.0%
github%2ecom/petar/GoHTTP/server.*Server·Read
0.0 0.0% 100.0% 2.5 1.2%
github%2ecom/petar/GoHTTP/server.*Server·extRevIter
0.0 0.0% 100.0% 193.5 96.0%
github%2ecom/petar/GoHTTP/server.*Server·process
0.0 0.0% 100.0% 3.5 1.7%
github%2ecom/petar/GoHTTP/server.*Server·read
0.0 0.0% 100.0% 3.0 1.5%
github%2ecom/petar/GoHTTP/server.*Server·subIter
0.0 0.0% 100.0% 1.5 0.7%
github%2ecom/petar/GoHTTP/server.*StampedServerConn·Read
0.0 0.0% 100.0% 190.0 94.3%
github%2ecom/petar/GoHTTP/server/subs.*StaticSub·Serve
0.0 0.0% 100.0% 188.0 93.3% io/ioutil.ReadFile
0.0 0.0% 100.0% 187.5 93.1% io/ioutil.readAll

Thanks,
--Petar

[Kyle Lemons]

You may want to either take a look at what's going on in your profilers or roll your own that shows you the data you want to look at.

For instance, the MemProfile call can either report all memory held by the runtime, or it can only report memory that hasn't been reclaimed by the GC.  It sounds like you are interested in both of these numbers, and most of the profilers I've looked at use one or the other (usually the former case).

[Petar Maymounkov]

I am using pprof.WriteHeapProfile, and my question is specifically
about its output.

Thanks,
--Petar

[Kyle Lemons]

Like I said.

http://golang.org/src/pkg/runtime/pprof/pprof.go?s=611:654#L31

[Russ Cox]

The heap profile tracks currently-in-use blocks of memory.
It is possible that the garbage collector has simply not run
(since it is allocation-triggered) and there is 200 MB of
garbage that will be collected at the next allocation.
It looks like the 200 MB was allocated by

GoHTTP/http.*ServerConn·Read
GoHTTP/http.NewBodyFile
GoHTTP/server.*Query·Write
GoHTTP/server.*Server·extRevIter
GoHTTP/server.*StampedServerConn·Read
GoHTTP/server/subs.*StaticSub·Serve
io/ioutil.ReadFile

Usually instead of running top10 to get the output
you showed, it is more interesting to run web and
look at the graph, which makes the relevant stack
traces easier to extract.

Russ