Identify Memory Leak Using pprof

Memory Leak : If a program/application keeps consuming lot of memory and the memory heap doesn't goes down even after some specific period of time, then it is considered a memory leak in that program. Normally the heap rise should get constant and get garbage collected after some time. If it is not happening, then the graph will keep increasing and increasing and can crash the application due to OOM (Out Of memory) errors.

How do we identify there is a memory leak ?

We can use Prometheus, CAdvisor kind of opensource tools to keep monitoring the process and heap size. If the graph generated in tools gives a saw tooth kind of graph, then there is a memory leak.

Saw Tooth graph is generated due to following situation:

• Memory heap keep increasing for a process running in docker and never it got garbage collected. Hence spike in the graph.
• After exceeding some heap limit, OOM error (Out of Memory) will happen and process and docker will be killed. Hence the sudden fall in the graph.
• According to docker restart policy, docker will come up again and the above steps continues.

How can we identify which part of the program is creating a memory leak ?

Golang provides tool called pprof which has rich features to identify and track memory leak. Sample program gives an idea how to use it.

File: main.go

package main
import (
        "fmt"
        "net/http"
        _ "net/http/pprof"
        "os"
        "time"
)
func go_ticker() {
        fmt.Println("Started go_ticker")
        tick := time.Tick(time.Second / 100)
        var buf []byte
        for range tick {
                // This portion of code can increase memory
                buf = append(buf, make([]byte, 1024*1024)...)
        }
        fmt.Println("Finished go_ticker")
}
func norm_ticker() {
        fmt.Println("Started norm_ticker")
        tick := time.Tick(time.Second / 100)
        var buf []byte
        for range tick {
                // This portion of code can increase memory
                buf = append(buf, make([]byte, 1024*1024)...)
        }
        fmt.Println("Finished norm_ticker")
}
func norm_10() {
        var buf []byte
        fmt.Println("Started norm_10")
        for i := 0; i < 10; i++ {
                buf = append(buf, make([]byte, 1024*1024)...)
        }
        fmt.Println("Finished norm_10")
}
func iter() {
        fmt.Println("Started iter")
        for i := 0; i < 10; i++ {
                fmt.Println("Iteration : ", i)
        }
        norm_ticker()
        fmt.Println("Finished iter")
}
// Run for a period of time: fatal error: runtime: out of memory
func main() {
        fmt.Println("Started main")
        // Open pprof
        go func() {
                ip := "0.0.0.0:6060"
                if err := http.ListenAndServe(ip, nil); err != nil {
                        fmt.Printf("start pprof failed on %s\n", ip)
                        os.Exit(1)
                }
        }()
        go go_ticker()
        norm_10()
        iter()
        fmt.Println("Finished main")
}

How to run and test ?

$ go get -u github.com/google/pprof
$ go build -o binary
$ time ./binary // Running the binary with time // Run this in terminal 1
$ go tool pprof http://localhost:6060/debug/pprof/heap // Generating a heap profile. Run this in terminal 2 when the above program is under execution
pprof> top // List all high heap consuming functions
pprof> top 5 // If your function list is too big, this command will show only top 5 functions
pprof> list main.go_ticker // This will show the internals of function where exectly the heap is formed
pprof> png // Generates a pictorial profile in PNG format
pprof> pdf // Generates a pictorial profile in pdf format
pprof> svg // Generates a pictorial profile in svg format

Technical

Flat and Flat%  : This will tell the memory allocated in that particular function
Cum and Cum%    : This will tell the cumulative heap data which includes memory created in its stack as well as called func.
                : In above example main.main calls main.iter() which inturn calls main.norm_ticker. If norm_ticker makes 100MB data and main.iter() makes another 20MB, the cum of main.main() is 120MB.

Heap Profile from above code

(pprof)
(pprof) top
Showing nodes accounting for 479.78MB, 100% of 479.78MB total
      flat  flat%   sum%        cum   cum%
  266.55MB 55.56% 55.56%   266.55MB 55.56%  main.go_ticker
  213.23MB 44.44%   100%   213.23MB 44.44%  main.norm_ticker
         0     0%   100%   213.23MB 44.44%  main.iter
         0     0%   100%   213.23MB 44.44%  main.main
         0     0%   100%   213.23MB 44.44%  runtime.main
(pprof)
(pprof)
(pprof)
(pprof) list main.norm_ticker
Total: 479.78MB
ROUTINE ======================== main.norm_ticker in /home/p4/Projects/go/sdpon/src/pprofandtrace/ticker/main.go
  213.23MB   213.23MB (flat, cum) 44.44% of Total
         .          .     21:func norm_ticker() {
         .          .     22:   fmt.Println("Started norm_ticker")
         .          .     23:   tick := time.Tick(time.Second / 100)
         .          .     24:   var buf []byte
         .          .     25:   for range tick {
  213.23MB   213.23MB     26:           buf = append(buf, make([]byte, 1024*1024)...)
         .          .     27:   }
         .          .     28:   fmt.Println("Finished norm_ticker")
         .          .     29:}
         .          .     30:
         .          .     31:func norm_10() {
(pprof)
(pprof)

PNG Graph generated from above execution

Sample Program without Http package

package main
import (
    "encoding/json"
    "io/ioutil"
    "log"
    "os"
    "runtime"
    "runtime/pprof"
)
func createHeapProfile() {
    f, err := os.Create("/tmp/heap.pprof")
    if err != nil {
            log.Fatal(err)
    }
    pprof.WriteHeapProfile(f)
    f.Close()
}
type A struct {
    Name string
}
type B struct {
    Li []A
}
func useIoutil(path string, jsonFile []byte) {
    err := ioutil.WriteFile(path, jsonFile, 0644)
    if err != nil {
            log.Fatal("Write-failed-for-key-values")
            return
    }
}
func main() {
    path := "/tmp/db"
    b := new(A)
    b.Name = "Raj"
    var li []A
    for i := 0; i < 10000000; i++ {
            li = append(li, *b)
    }
    bkps := new(B)
    bkps.Li = li
    json.Marshal(bkps)
    jsonFile, _ := json.MarshalIndent(bkps, "", " ")
    useIoutil(path, jsonFile)
    // runtime.GC() // This piece of code will execute immediate garbage collector.
    createHeapProfile()
}

How to analyze heap profile ?

$ go run main.go
$ go tool pprof /tmp/heap.pprof
File: main
Type: inuse_space
Time: Aug 2, 2021 at 4:59am (UTC)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 572.06MB, 100% of 572.06MB total
Showing top 10 nodes out of 12
      flat  flat%   sum%        cum   cum%
  271.08MB 47.39% 47.39%   271.08MB 47.39%  bytes.makeSlice
  157.93MB 27.61% 74.99%   572.06MB   100%  main.main
  143.05MB 25.01%   100%   414.13MB 72.39%  encoding/json.Marshal
         0     0%   100%   271.08MB 47.39%  bytes.(*Buffer).WriteString
         0     0%   100%   271.08MB 47.39%  bytes.(*Buffer).grow
         0     0%   100%   271.08MB 47.39%  encoding/json.(*encodeState).marshal
         0     0%   100%   271.08MB 47.39%  encoding/json.(*encodeState).reflectValue
         0     0%   100%   271.08MB 47.39%  encoding/json.arrayEncoder.encode
         0     0%   100%   271.08MB 47.39%  encoding/json.ptrEncoder.encode
         0     0%   100%   271.08MB 47.39%  encoding/json.sliceEncoder.encode
(pprof)
(pprof) top 2
Showing nodes accounting for 429.01MB, 74.99% of 572.06MB total
Showing top 2 nodes out of 12
      flat  flat%   sum%        cum   cum%
  271.08MB 47.39% 47.39%   271.08MB 47.39%  bytes.makeSlice
  157.93MB 27.61% 74.99%   572.06MB   100%  main.main
(pprof)
(pprof)