echo list | go tool pprof -alloc_space gateway http://10.2.1.93:8421/debug/pprof/heap > abc.log


echo list | go tool pprof -inuse_space gateway http://10.2.1.93:8421/debug/pprof/heap > inuse.log


Understanding Go Lang Memory Usage

Mon, Dec 22, 2014

Warning: This is an intro to memory with the go language - you can deep dive down the rabbit hole as far as you want to go.

Most beginning go developers try out a simple hello world ala:

package main

import (
"fmt"
"time"
)

func main() {
fmt.Println("hi")

time.Sleep(30 * time.Second)
}

and then they go completely crazy.

138 f!*%!G of $%@# memory!? This laptop only has 16G!

Virtual vs Resident

Go manages memory differently than what you might be used to. It will reserve a large chunk right off the bat (VIRT) but your (RSS) is much closer to reality of what is in use.

What is the difference between RSS and VIRT ?

VIRT or the virtual address space size is the amount that a program has mapped in and is able to access.

RSS or the resident set size is the amount of memory actually in use.

If you are curious about how go actually goes about doing this check out:

​https://github.com/golang/go/blob/master/src/runtime/malloc1.go​

    // On a 64-bit machine, allocate from a single contiguous     // reservation.     // 128 GB (MaxMem) should be big enough for now.      // Actually we reserve 136 GB (because the bitmap ends up being 8     // GB) 

It’s important to note that if you are using 32bit arch the memory reservation is done completely differently.

Garbage Collection

Now that we know the difference between resident and shared memory we can talk about how go does garbage collection to understand how our program is working.

Chances are you are writing some long lived daemon - be it a web app server or something more complex. Generally you will probably make quite a few allocations throughout it’s lifetime. Knowing how the memory is dealt with is essential.

Typically if you go 2 minutes without garbage collection it will get ran. If a span goes unused for 5 minutes the scavenger allows it to be released.

So if you suspect that your memory usage should be going back down give it ~ 7 minutes just to verify.

Be aware that currently the gc is non-compacting - what this really means is that if you have a single byte touching a page - the scavenger will be prevented from madvising it.

Last but not least - on go 1.3 goroutine stacks, which are 8k/pop, don’t get released - they get re-used later on. Don’t fret though - Go still has plenty of room for improvement in the GC department. So if your code is spawning a ton of goroutines and your RES is staying high this could be why.

So, now we know what to look at it from outside our program and we know what to expect from GC.

Analyzing Memory Usage.

Let’s take a small example to how we might look at our memory. In our example we’ll allocate 10 sets of 100 megabytes.

Then we’ll include a couple different ways of looking at the memory usage.

One method is by using the runtime package and looking at the ReadMemStats function.

The other method is using this super sweet web interface via the pprof package. This allows us to remotely grab our pprof data which we’ll explore shortly.

Yet another method which ​​Dave Cheney​​ mentioned we should mention is to use the gctrace debug environment variable.

Note: This was done on 64bit linux with go 1.4.

package main

import (
"log"
"net/http"
_ "net/http/pprof"
"runtime"
"sync"
)

func bigBytes() *[]byte {
s := make([]byte, 100000000)
return &s
}

func main() {
var wg sync.WaitGroup

go func() {
log.Println(http.ListenAndServe("localhost:6060", nil))
}()

var mem runtime.MemStats
runtime.ReadMemStats(&mem)
log.Println(mem.Alloc)
log.Println(mem.TotalAlloc)
log.Println(mem.HeapAlloc)
log.Println(mem.HeapSys)

for i := 0; i < 10; i++ {
s := bigBytes()
if s == nil {
log.Println("oh noes")
}
}

runtime.ReadMemStats(&mem)
log.Println(mem.Alloc)
log.Println(mem.TotalAlloc)
log.Println(mem.HeapAlloc)
log.Println(mem.HeapSys)

wg.Add(1)
wg.Wait()

}

There are typically two options you might choose when using pprof to look at memory.

One option is ‘–alloc_space’ which tells you how many megabytes have been allocated.

The other – ‘–inuse_space’ tells you know how many are still in use.

We can launch pprof and point it at our in-app webserver to get the topk abusers.

Then if we want we can use list to see where some of that usage is coming from:

In Use

vagrant@vagrant-ubuntu-raring-64:~/blahdo$ go tool pprof -inuse_space blahdo http://localhost:6060/debug/pprof/heap Fetching profile from http://localhost:6060/debug/pprof/heap Saved profile in /home/vagrant/pprof/pprof.blahdo.localhost:6060.inuse_objects.inuse_space.025.pb.gz Entering interactive mode (type "help" for commands) (pprof) top5 190.75MB of 191.25MB total (99.74%) Dropped 3 nodes (cum <= 0.96MB)       flat  flat%   sum%        cum   cum%   190.75MB 99.74% 99.74%   190.75MB 99.74%  main.main          0     0% 99.74%   190.75MB 99.74%  runtime.goexit          0     0% 99.74%   190.75MB 99.74%  runtime.main (pprof) quit 

Allocated

vagrant@vagrant-ubuntu-raring-64:~/blahdo$ go tool pprof -alloc_space blahdo http://localhost:6060/de bug/pprof/heap Fetching profile from http://localhost:6060/debug/pprof/heap Saved profile in /home/vagrant/pprof/pprof.blahdo.localhost:6060.alloc_objects.alloc_space.027.pb.gz Entering interactive mode (type "help" for commands) (pprof) top5 572.25MB of 572.75MB total (99.91%) Dropped 3 nodes (cum <= 2.86MB)       flat  flat%   sum%        cum   cum%   572.25MB 99.91% 99.91%   572.25MB 99.91%  main.main          0     0% 99.91%   572.25MB 99.91%  runtime.goexit          0     0% 99.91%   572.25MB 99.91%  runtime.main 

Topk is nice but what is nicer is the list command where we can see where the actual damage is being done in context to the rest of the program.

(pprof) list Total: 572.75MB ROUTINE ======================== main.main in /home/vagrant/blahdo/main.go   572.25MB   572.25MB (flat, cum) 99.91% of Total          .          .     23:   var mem runtime.MemStats          .          .     24:   runtime.ReadMemStats(&mem)          .          .     25:   log.Println(mem.Alloc)          .          .     26:          .          .     27:   for i := 0; i < 10; i++ {   572.25MB   572.25MB     28:           s := bigBytes()          .          .     29:           if s == nil {          .          .     30:                   log.Println("oh noes")          .          .     31:           }          .          .     32:   }          .          .     33: 

Those of you following at home have probably noticed quite a few differences in the memory usage being reported – why is that?

Let’s look at ps =>

vagrant@vagrant-ubuntu-raring-64:~$ ps aux | grep blahdo vagrant   4817  0.2 10.7 699732 330524 pts/1   Sl+  00:13   0:00 ./blahdo 

Now let’s look at our log output =>

./vagrant@vagrant-ubuntu-raring-64:~/blahdo$ ./blahdo 2014/12/23 00:19:37 279672 2014/12/23 00:19:37 336152 2014/12/23 00:19:37 279672 2014/12/23 00:19:37 819200 2014/12/23 00:19:37 300209920 2014/12/23 00:19:37 1000420968 2014/12/23 00:19:37 300209920 2014/12/23 00:19:37 500776960 

Finally - let’s look at at using gctrace:

vagrant@vagrant-ubuntu-raring-64:~/blahdo$ GODEBUG=gctrace=1 ./blahdo gc1(1): 1+0+95+0 us, 0 -> 0 MB, 21 (21-0) objects, 2 goroutines, 15/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc2(1): 0+0+81+0 us, 0 -> 0 MB, 52 (53-1) objects, 3 goroutines, 20/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc3(1): 0+0+77+0 us, 0 -> 0 MB, 151 (169-18) objects, 4 goroutines, 25/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc4(1): 0+0+110+0 us, 0 -> 0 MB, 325 (393-68) objects, 4 goroutines, 33/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc5(1): 0+0+138+0 us, 0 -> 0 MB, 351 (458-107) objects, 4 goroutines, 40/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields 2014/12/23 02:27:14 277960 2014/12/23 02:27:14 332680 2014/12/23 02:27:14 277960 2014/12/23 02:27:14 884736 gc6(1): 1+0+181+0 us, 0 -> 95 MB, 599 (757-158) objects, 6 goroutines, 52/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc7(1): 1+0+454+19 us, 95 -> 286 MB, 438 (759-321) objects, 6 goroutines, 52/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc8(1): 1+0+167+0 us, 190 -> 477 MB, 440 (762-322) objects, 6 goroutines, 54/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc9(1): 2+0+191+0 us, 190 -> 477 MB, 440 (765-325) objects, 6 goroutines, 54/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields 2014/12/23 02:27:14 300206864 2014/12/23 02:27:14 1000417040 2014/12/23 02:27:14 300206864 2014/12/23 02:27:14 500842496 GC forced gc10(1): 3+0+1120+22 us, 190 -> 286 MB, 455 (789-334) objects, 6 goroutines, 54/31/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields scvg0: inuse: 96, idle: 381, sys: 477, released: 0, consumed: 477 (MB) GC forced gc11(1): 2+0+270+0 us, 95 -> 95 MB, 438 (789-351) objects, 6 goroutines, 54/39/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields scvg1: 0 MB released scvg1: inuse: 96, idle: 381, sys: 477, released: 0, consumed: 477 (MB) GC forced gc12(1): 85+0+353+1 us, 95 -> 95 MB, 438 (789-351) objects, 6 goroutines, 54/37/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields 

This is important because most ops tools will be looking at your application from the operating system’s point of view - not necessarily what is truly going on.

More options can be found in the ​​runtime package​

Short Answer:


  • RES - will show what the process has at that moment but it might not include anything that has not been paged in or has been paged out.
  • mem.Alloc - these are the bytes that were allocated and still in use
  • mem.TotalAlloc - what we allocated throughout the lifetime
  • mem.HeapAlloc - what’s being used on the heap right now
  • mem.HeapSys - this includes what is being used by the heap and what has been reclaimed but not given back out

Further - it is important to note that with pprof you are only getting a sampling - not the true values.

In general - when looking at this sort of stuff it’s best to not focus on the numbers but focus on the problem.

We at deferpanic believe in measuring everything but we feel “modern day” ops tools are horrible and focus on the effect of a problem but not the actual problem.

If your car won’t start you may think that it is the problem but it’s not. It’s not even the fact that the gastank is empty. The real problem is that you did not put gas into the gastank and now you are noticing a stream of consequences from the original problem.

If you were just monitoring the RES output from ps for a go binary - it might tell you that there’s a problem but you have no clue what the problem is until you start deep diving. We want to fix that.

Edit:

The next paragraph is left un-edited. It was not written to degrade ops or devops people. The intent was to show the difference between app level metrics and os level metrics. We realize this was not written well and apologize. We feel that existing ‘ops’ tools don’t give the developer the full information needed to fix their problems.

We also feel that existing app level metric tools leave a lot to desire.

Ops people play a very vital role and we are extremely thankful for all their work - indeed it’s the developers code that is messing things up - this is what we are looking at.

End Edit

Let the ops people have their 300+ graphs with a bajillion gauges and counters and meters and histograms. As people who actually write software we are more interested in finding the real solution by finding the real problem.