Google App Engine Go memory management

I've run into a problem recently where App Engine would terminate my Go instance because it says it ran out of memory. The memory limit for the instance is set to 128Mb.

However, I have trouble figuring out where all that memory is being allocated. When I run the following code:

<!-- language: go -->

var s runtime.MemStats
runtime.ReadMemStats(&s)
c.Debugf("allocated memory: %d", s.Alloc)

it shows me that when allocated memory reaches about 39-40Mb, my app gets terminated with the following error:

> Exceeded soft private memory limit with 135.082 MB after servicing 1 requests total

Similarly, when runtime.ReadMemStats(&s) indicates that I'm using 20 Mb, the App Engine console shows that my instance is using 92Mb. Redoing the same request, runtime.ReadMemStats(&s) still shows 20Mb, while the App Engine console shows 119Mb.

I have disabled appstats, still no help.

Most of my memory is used up by a memory cache, which I could reduce to fit into the constraints (or increase the memory limit on my instance), but I'd like to know where all that memory is being used. If someone could shed some light on that, or how to correctly profile memory usage on App Engine, that would help a lot.

Update: managed to reproduce this locally.

The following is a sample application that allocates some integers in one request and garbage collects them in the next request:

// Package test implements a simple memory test for Google App Engine.
package test

import (
	"net/http"
	"runtime"

	"appengine"
)

var buffer []int64

func init() {
	http.HandleFunc("/", handler)
}

func handler(w http.ResponseWriter, r *http.Request) {
	var s runtime.MemStats
	c := appengine.NewContext(r)
	if len(buffer) == 0 {
		// Allocate 2^22 integers.
		runtime.ReadMemStats(&s)
		c.Debugf("Memory usage: %d bytes (%d system).", s.Alloc, s.Sys)
		buffer = make([]int64, 4*1024*1024)
		for i, _ := range buffer {
			buffer[i] = int64(i*i)
		}
		runtime.ReadMemStats(&s)
		c.Debugf("Memory usage increased to: %d bytes (%d system).", s.Alloc, s.Sys)
	} else {
		// Remove all references to the slice pointed to by buffer.
		// This should mark it for garbage collection.
		runtime.ReadMemStats(&s)
		c.Debugf("Memory usage: %d bytes (%d system).", s.Alloc, s.Sys)
		buffer = nil
		runtime.GC()
		runtime.ReadMemStats(&s)
		c.Debugf("After GC event: %d bytes (%d system).", s.Alloc, s.Sys)
	}
	w.WriteHeader(http.StatusTeapot)
}

When run using the development server:

$ ./go_appengine/dev_appserver.py test

2013/09/16 12:28:28 DEBUG: Memory usage: 833096 bytes (272681032 system).
2013/09/16 12:28:28 DEBUG: Memory usage increased to: 34335216 bytes (308332616 system).
INFO     2013-09-16 12:28:28,884 module.py:593] default: "GET / HTTP/1.1" 418 -
2013/09/16 12:28:29 DEBUG: Memory usage: 34345896 bytes (308332616 system).
2013/09/16 12:28:29 DEBUG: After GC event: 781504 bytes (308332616 system).
INFO     2013-09-16 12:28:29,560 module.py:593] default: "GET / HTTP/1.1" 418 -
2013/09/16 12:28:30 DEBUG: Memory usage: 791616 bytes (308332616 system).
2013/09/16 12:28:30 DEBUG: Memory usage increased to: 34337392 bytes (308332616 system).
INFO     2013-09-16 12:28:30,276 module.py:593] default: "GET / HTTP/1.1" 418 -
2013/09/16 12:28:36 DEBUG: Memory usage: 34347536 bytes (308332616 system).
2013/09/16 12:28:36 DEBUG: After GC event: 783632 bytes (308332616 system).
INFO     2013-09-16 12:28:36,224 module.py:593] default: "GET / HTTP/1.1" 418 -

It appears that memory allocation and garbage collection works fine. However, looking at ps output, it seems that deallocating memory does not decrease the virtual memory usage of the process:

$ ps axo command,vsize,rss | ag go_app
/usr/bin/python2.7 ./go_app 381248 56608
$ ps axo command,vsize,rss | ag go_app
/usr/bin/python2.7 ./go_app 676324 57652
$ ps axo command,vsize,rss | ag go_app
/usr/bin/python2.7 ./go_app 750056 57856
$ ps axo command,vsize,rss | ag go_app
/usr/bin/python2.7 ./go_app 750056 57856

It seems that the Python process that runs the underlying Go instance keeps growing its virtual memory, but it never gets freed. It also seems that a similar thing happens on the production server: the allocated memory reported by the instance runtime is different than the used memory reported by the kernel.

As suggested by @Kluyg, it seems that the admin console shows the system allocated memory, which makes sense.

According to the docs Alloc field shows bytes allocated and still in use. In garbage-collected language, however, when memory is released by GC, it doesn't immediately returned to the system (it can be requested again soon, so why bother returning it back?). So what you really need to monitor is Sys field which counts bytes obtained from the system.
You may be interested in this article with some insights how to minimise memory usage.