How to interpret pprof output?
I'm trying to profile an application written in go which apparently uses about 256 virtual memory (checked using ps aux). I'm trying to use pprof package and see what functions allocate/consume most of the memory but the results make no sense to me. pprof top seems to list only the runtime functions. Can someone help me understand this data?
ps aux |grep android
root 4584 3.4 0.1 500244 29536 pts/1 Sl+ 17:21 0:38 ./android -logtostderr
go tool pprof http://localhost:6060/debug/pprof/heap
/pprof.localhost:6060.inuse_objects.inuse_space.008.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top
512.19kB of 512.19kB total ( 100%)
Dropped 19 nodes (cum <= 2.56kB)
flat flat% sum% cum cum%
512.19kB 100% 100% 512.19kB 100% runtime.malg
0 0% 100% 512.19kB 100% runtime.mcommoninit
0 0% 100% 512.19kB 100% runtime.mpreinit
0 0% 100% 512.19kB 100% runtime.rt0_go
0 0% 100% 512.19kB 100% runtime.schedinit
(pprof)
http://localhost:6060/debug/pprof/heap?debug=1
heap profile: 3: 49632 [3: 49632] @ heap/1048576
1: 49152 [1: 49152] @ 0x412c62 0x411bc9 0x6fd8c8 0x649c40 0x5497e6 0x409ad2 0x43615f 0x4669c1
# 0x6fd8c8 html.init+0xe8 /usr/local/gosrc/src/html/entity.go:2154
# 0x649c40 html/template.init+0x70 /usr/local/gosrc/src/html/template/url.go:105
# 0x5497e6 net/http/pprof.init+0x56 /usr/local/gosrc/src/net/http/pprof/pprof.go:239
# 0x409ad2 main.init+0x92 /root/go/src/github.com/ginkoob/devmg/local/android/local.go:236
# 0x43615f runtime.main+0x27f /usr/local/gosrc/src/runtime/proc.go:100
1: 384 [1: 384] @ 0x43d0e7 0x4317ef 0x437700 0x4372a9 0x464182
# 0x43d0e7 runtime.malg+0x27 /usr/local/gosrc/src/runtime/proc1.go:2172
# 0x4317ef runtime.mpreinit+0x1f /usr/local/gosrc/src/runtime/os1_linux.go:197
# 0x437700 runtime.mcommoninit+0x100 /usr/local/gosrc/src/runtime/proc1.go:114
# 0x4372a9 runtime.schedinit+0x79 /usr/local/gosrc/src/runtime/proc1.go:57
# 0x464182 runtime.rt0_go+0x132 /usr/local/gosrc/src/runtime/asm_amd64.s:109
1: 96 [1: 96] @ 0x449005 0x46a114 0x468625 0x467e71 0x4069d5 0x436190 0x4669c1
# 0x46a114 golang.org/x/mobile/gl.DoWork+0x54 /root/go/src/golang.org/x/mobile/gl/work.go:82
# 0x468625 golang.org/x/mobile/app.main+0x1d5 /root/go/src/golang.org/x/mobile/app/x11.go:65
# 0x467e71 golang.org/x/mobile/app.Main+0x21 /root/go/src/golang.org/x/mobile/app/app.go:22
# 0x4069d5 main.main+0x75 /root/go/src/github.com/ginkoob/devmg/local/android/local.go:65
# 0x436190 runtime.main+0x2b0 /usr/local/gosrc/src/runtime/proc.go:111
0: 0 [0: 0] @ 0x449005 0x6529f5 0x652936 0x64e2c4 0x54932e 0x549540 0x5222aa 0x523b0d 0x52457e 0x521d6e 0x4669c1
# 0x6529f5 runtime/pprof.writeGoroutineStacks+0x45 /usr/local/gosrc/src/runtime/pprof/pprof.go:514
# 0x652936 runtime/pprof.writeGoroutine+0x46 /usr/local/gosrc/src/runtime/pprof/pprof.go:505
# 0x64e2c4 runtime/pprof.(*Profile).WriteTo+0xd4 /usr/local/gosrc/src/runtime/pprof/pprof.go:236
# 0x54932e net/http/pprof.handler.ServeHTTP+0x37e /usr/local/gosrc/src/net/http/pprof/pprof.go:199
# 0x549540 net/http/pprof.Index+0x200 /usr/local/gosrc/src/net/http/pprof/pprof.go:211
# 0x5222aa net/http.HandlerFunc.ServeHTTP+0x3a /usr/local/gosrc/src/net/http/server.go:1422
# 0x523b0d net/http.(*ServeMux).ServeHTTP+0x17d /usr/local/gosrc/src/net/http/server.go:1699
# 0x52457e net/http.serverHandler.ServeHTTP+0x19e /usr/local/gosrc/src/net/http/server.go:1862
# 0x521d6e net/http.(*conn).serve+0xbee /usr/local/gosrc/src/net/http/server.go:1361
# runtime.MemStats
# Alloc = 2701264
# TotalAlloc = 2701264
# Sys = 7145720
# Lookups = 18
# Mallocs = 19841
# Frees = 0
# HeapAlloc = 2701264
# HeapSys = 3637248
# HeapIdle = 262144
# HeapInuse = 3375104
# HeapReleased = 0
# HeapObjects = 19841
# Stack = 557056 / 557056
# MSpan = 28896 / 32768
# MCache = 4832 / 16384
# BuckHashSys = 1443979
# NextGC = 4194304
# PauseNs = [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# NumGC = 0
# EnableGC = true
# DebugGC = false
http://localhost:6060/debug/pprof/goroutine?debug=1
goroutine profile: total 31
1 @ 0x652ba8 0x652983 0x64e2c4 0x54932e 0x549540 0x5222aa 0x523b0d 0x52457e 0x521d6e 0x4669c1
# 0x652ba8 runtime/pprof.writeRuntimeProfile+0xb8 /usr/local/gosrc/src/runtime/pprof/pprof.go:545
# 0x652983 runtime/pprof.writeGoroutine+0x93 /usr/local/gosrc/src/runtime/pprof/pprof.go:507
# 0x64e2c4 runtime/pprof.(*Profile).WriteTo+0xd4 /usr/local/gosrc/src/runtime/pprof/pprof.go:236
# 0x54932e net/http/pprof.handler.ServeHTTP+0x37e /usr/local/gosrc/src/net/http/pprof/pprof.go:199
# 0x549540 net/http/pprof.Index+0x200 /usr/local/gosrc/src/net/http/pprof/pprof.go:211
# 0x5222aa net/http.HandlerFunc.ServeHTTP+0x3a /usr/local/gosrc/src/net/http/server.go:1422
# 0x523b0d net/http.(*ServeMux).ServeHTTP+0x17d /usr/local/gosrc/src/net/http/server.go:1699
# 0x52457e net/http.serverHandler.ServeHTTP+0x19e /usr/local/gosrc/src/net/http/server.go:1862
# 0x521d6e net/http.(*conn).serve+0xbee /usr/local/gosrc/src/net/http/server.go:1361
1 @ 0x436573 0x444ce4 0x444242 0x46871a 0x467e71 0x4069d5 0x436190 0x4669c1
# 0x46871a golang.org/x/mobile/app.main+0x2ca /root/go/src/golang.org/x/mobile/app/x11.go:61
# 0x467e71 golang.org/x/mobile/app.Main+0x21 /root/go/src/golang.org/x/mobile/app/app.go:22
# 0x4069d5 main.main+0x75 /root/go/src/github.com/nme/devmg/local/android/local.go:65
# 0x436190 runtime.main+0x2b0 /usr/local/gosrc/src/runtime/proc.go:111
1 @ 0x4669c1
1 @ 0x436573 0x436634 0x436378 0x4669c1
# 0x436573 runtime.gopark+0x163 /usr/local/gosrc/src/runtime/proc.go:186
# 0x436634 runtime.goparkunlock+0x54 /usr/local/gosrc/src/runtime/proc.go:191
# 0x436378 runtime.forcegchelper+0xb8 /usr/local/gosrc/src/runtime/proc.go:152
1 @ 0x436573 0x436634 0x42630d 0x4669c1
# 0x436573 runtime.gopark+0x163 /usr/local/gosrc/src/runtime/proc.go:186
# 0x436634 runtime.goparkunlock+0x54 /usr/local/gosrc/src/runtime/proc.go:191
# 0x42630d runtime.bgsweep+0x14d /usr/local/gosrc/src/runtime/mgcsweep.go:67
1 @ 0x436573 0x436634 0x41e04a 0x4669c1
# 0x436573 runtime.gopark+0x163 /usr/local/gosrc/src/runtime/proc.go:186
# 0x436634 runtime.goparkunlock+0x54 /usr/local/gosrc/src/runtime/proc.go:191
# 0x41e04a runtime.runfinq+0xaa /usr/local/gosrc/src/runtime/mfinal.go:154
1 @ 0x436573 0x444ce4 0x444242 0x4691e7 0x4669c1
# 0x4691e7 golang.org/x/mobile/app.pump.func1+0x527 /root/go/src/golang.org/x/mobile/app/app.go:138
1 @ 0x436573 0x436634 0x40d611 0x40ccfb 0x4acb57 0x4669c1
# 0x4acb57 github.com/golang/glog.(*loggingT).flushDaemon+0x67 /root/go/src/github.com/golang/glog/glog.go:882
1 @ 0x4173be 0x45142e 0x4669c1
# 0x4173be runtime.notetsleepg+0x4e /usr/local/gosrc/src/runtime/lock_futex.go:203
# 0x45142e runtime.timerproc+0xde /usr/local/gosrc/src/runtime/time.go:209
1 @ 0x436573 0x444ce4 0x444242 0x533327 0x4669c1
# 0x533327 net/http.(*persistConn).readLoop+0xac7 /usr/local/gosrc/src/net/http/transport.go:983
1 @ 0x436573 0x43069e 0x42fb60 0x4cd99a 0x4cda06 0x4d158c 0x4ef94d 0x5254d1 0x524853 0x524716 0x524daf 0x408e1c 0x4669c1
# 0x42fb60 net.runtime_pollWait+0x60 /usr/local/gosrc/src/runtime/netpoll.go:157
# 0x4cd99a net.(*pollDesc).Wait+0x3a /usr/local/gosrc/src/net/fd_poll_runtime.go:73
# 0x4cda06 net.(*pollDesc).WaitRead+0x36 /usr/local/gosrc/src/net/fd_poll_runtime.go:78
# 0x4d158c net.(*netFD).accept+0x27c /usr/local/gosrc/src/net/fd_unix.go:408
# 0x4ef94d net.(*TCPListener).AcceptTCP+0x4d /usr/local/gosrc/src/net/tcpsock_posix.go:254
# 0x5254d1 net/http.tcpKeepAliveListener.Accept+0x41 /usr/local/gosrc/src/net/http/server.go:2138
# 0x524853 net/http.(*Server).Serve+0xb3 /usr/local/gosrc/src/net/http/server.go:1887
# 0x524716 net/http.(*Server).ListenAndServe+0x136 /usr/local/gosrc/src/net/http/server.go:1877
# 0x524daf net/http.ListenAndServe+0x8f /usr/local/gosrc/src/net/http/server.go:1967
# 0x408e1c main.main.func1+0x3c /root/go/src/github.com/nme/devmg/local/android/local.go:40
1 @ 0x436573 0x43069e 0x42fb60 0x4cd99a 0x4cda06 0x4cf74a 0x4e3c34 0x5c0c39 0x5c14aa 0x4b0cee 0x4b5b43 0x49e028 0x49a8d0 0x49b173 0x49cf47 0x4669c1
# 0x42fb60 net.runtime_pollWait+0x60 /usr/local/gosrc/src/runtime/netpoll.go:157
# 0x4cd99a net.(*pollDesc).Wait+0x3a /usr/local/gosrc/src/net/fd_poll_runtime.go:73
# 0x4cda06 net.(*pollDesc).WaitRead+0x36 /usr/local/gosrc/src/net/fd_poll_runtime.go:78
# 0x4cf74a net.(*netFD).Read+0x23a /usr/local/gosrc/src/net/fd_unix.go:232
# 0x4e3c34 net.(*conn).Read+0xe4 /usr/local/gosrc/src/net/net.go:132
# 0x5c0c39 bufio.(*Reader).fill+0x1e9 /usr/local/gosrc/src/bufio/bufio.go:97
# 0x5c14aa bufio.(*Reader).ReadByte+0x7a /usr/local/gosrc/src/bufio/bufio.go:229
# 0x4b0cee golang.org/x/net/websocket.hybiFrameReaderFactory.NewFrameReader+0xbe /root/go/src/golang.org/x/net/websocket/hybi.go:126
# 0x4b5b43 golang.org/x/net/websocket.Codec.Receive+0x183 /root/go/src/golang.org/x/net/websocket/websocket.go:315
# 0x49e028 golang.org/x/net/websocket.(Codec).Receive-fm+0x58 /root/go/src/github.com/nme/socks/ws.go:420
# 0x49a8d0 github.com/nme/socks.(*WSConn).execute+0x210 /root/go/src/github.com/nme/socks/ws.go:389
# 0x49b173 github.com/nme/socks.(*WSConn).receiveMessage+0x203 /root/go/src/github.com/nme/socks/ws.go:420
# 0x49cf47 github.com/nme/socks.(*WSConn).Setup.func3+0x117 /root/go/src/github.com/nme/socks/ws.go:221
1 @ 0x436573 0x436634 0x40d611 0x40ccfb 0x4080af 0x406fd8 0x4092e7 0x46937f 0x4669c1
# 0x4080af main.startSocks+0x3bf /root/go/src/github.com/nme/devmg/local/android/local.go:151
# 0x406fd8 main.startClient+0x5d8 /root/go/src/github.com/nme/devmg/local/android/local.go:82
# 0x4092e7 main.main.func2+0x227 /root/go/src/github.com/nme/devmg/local/android/local.go:64
# 0x46937f golang.org/x/mobile/app.main.func1+0x6f /root/go/src/golang.org/x/mobile/app/x11.go:51
1 @ 0x436573 0x444ce4 0x444242 0x533c4c 0x4669c1
# 0x533c4c net/http.(*persistConn).writeLoop+0x40c /usr/local/gosrc/src/net/http/transport.go:1016
1 @ 0x436573 0x436634 0x40d182 0x40ccfb 0x408f63 0x4669c1
# 0x408f63 main.main.func2.1+0x73 /root/go/src/github.com/nme/devmg/local/android/local.go:47
1 @ 0x436573 0x444ce4 0x444242 0x49dcee 0x4669c1
# 0x49dcee github.com/nme/socks.(*WSConn).Setup.func4+0x86e /root/go/src/github.com/nme/socks/ws.go:256
1 @ 0x436573 0x444ce4 0x444242 0x49c7a5 0x4669c1
# 0x49c7a5 github.com/nme/socks.SetKeepAlive.func1+0x215 /root/go/src/github.com/nme/socks/ws.go:32
1 @ 0x436573 0x436634 0x40d611 0x40ccfb 0x4072c6 0x4669c1
# 0x4072c6 main.WaitCmd+0xc6 /root/go/src/github.com/nme/devmg/local/android/local.go:95
1 @ 0x436573 0x444ce4 0x444242 0x4998aa 0x4669c1
# 0x4998aa github.com/nme/socks.(*Router).ListenAndServe+0x91a /root/go/src/github.com/nme/socks/ws.go:124
1 @ 0x436573 0x444ce4 0x444242 0x49a173 0x4669c1
# 0x49a173 github.com/nme/socks.(*WSConn).Setup+0x753 /root/go/src/github.com/nme/socks/ws.go:186
1 @ 0x436573 0x436634 0x40d611 0x40ccfb 0x49b3ea 0x4669c1
# 0x49b3ea github.com/nme/socks.(*Nic).Dial.func1+0x9a /root/go/src/github.com/nme/socks/conn.go:34
3 @ 0x436573 0x444ce4 0x444242 0x49cd50 0x4669c1
# 0x49cd50 github.com/nme/socks.(*Router).ListenAndServe.func1+0x590 /root/go/src/github.com/nme/socks/ws.go:96
1 @ 0x436573 0x43069e 0x42fb60 0x4cd99a 0x4cda06 0x4cf74a 0x4e3c34 0x51a734 0x581f7d 0x5c0c39 0x5c1aaa 0x5c1b23 0x6285f1 0x628360 0x515496 0x51d83f 0x5218a7 0x4669c1
# 0x42fb60 net.runtime_pollWait+0x60 /usr/local/gosrc/src/runtime/netpoll.go:157
# 0x4cd99a net.(*pollDesc).Wait+0x3a /usr/local/gosrc/src/net/fd_poll_runtime.go:73
# 0x4cda06 net.(*pollDesc).WaitRead+0x36 /usr/local/gosrc/src/net/fd_poll_runtime.go:78
# 0x4cf74a net.(*netFD).Read+0x23a /usr/local/gosrc/src/net/fd_unix.go:232
# 0x4e3c34 net.(*conn).Read+0xe4 /usr/local/gosrc/src/net/net.go:132
# 0x51a734 net/http.(*liveSwitchReader).Read+0xa4 /usr/local/gosrc/src/net/http/server.go:219
# 0x581f7d io.(*LimitedReader).Read+0xbd /usr/local/gosrc/src/io/io.go:427
# 0x5c0c39 bufio.(*Reader).fill+0x1e9 /usr/local/gosrc/src/bufio/bufio.go:97
# 0x5c1aaa bufio.(*Reader).ReadSlice+0x21a /usr/local/gosrc/src/bufio/bufio.go:328
# 0x5c1b23 bufio.(*Reader).ReadLine+0x53 /usr/local/gosrc/src/bufio/bufio.go:357
# 0x6285f1 net/textproto.(*Reader).readLineSlice+0x81 /usr/local/gosrc/src/net/textproto/reader.go:55
# 0x628360 net/textproto.(*Reader).ReadLine+0x40 /usr/local/gosrc/src/net/textproto/reader.go:36
# 0x515496 net/http.ReadRequest+0xb6 /usr/local/gosrc/src/net/http/request.go:653
# 0x51d83f net/http.(*conn).readRequest+0x32f /usr/local/gosrc/src/net/http/server.go:633
# 0x5218a7 net/http.(*conn).serve+0x727 /usr/local/gosrc/src/net/http/server.go:1319
1 @ 0x436573 0x43069e 0x42fb60 0x4cd99a 0x4cda06 0x4cf74a 0x4e3c34 0x51a734 0x581f7d 0x5c0c39 0x5c0e5c 0x51d7cb 0x5218a7 0x4669c1
# 0x42fb60 net.runtime_pollWait+0x60 /usr/local/gosrc/src/runtime/netpoll.go:157
# 0x4cd99a net.(*pollDesc).Wait+0x3a /usr/local/gosrc/src/net/fd_poll_runtime.go:73
# 0x4cda06 net.(*pollDesc).WaitRead+0x36 /usr/local/gosrc/src/net/fd_poll_runtime.go:78
# 0x4cf74a net.(*netFD).Read+0x23a /usr/local/gosrc/src/net/fd_unix.go:232
# 0x4e3c34 net.(*conn).Read+0xe4 /usr/local/gosrc/src/net/net.go:132
# 0x51a734 net/http.(*liveSwitchReader).Read+0xa4 /usr/local/gosrc/src/net/http/server.go:219
# 0x581f7d io.(*LimitedReader).Read+0xbd /usr/local/gosrc/src/io/io.go:427
# 0x5c0c39 bufio.(*Reader).fill+0x1e9 /usr/local/gosrc/src/bufio/bufio.go:97
# 0x5c0e5c bufio.(*Reader).Peek+0xcc /usr/local/gosrc/src/bufio/bufio.go:132
# 0x51d7cb net/http.(*conn).readRequest+0x2bb /usr/local/gosrc/src/net/http/server.go:629
# 0x5218a7 net/http.(*conn).serve+0x727 /usr/local/gosrc/src/net/http/server.go:1319
1 @ 0x436573 0x436634 0x42051b 0x4669c1
# 0x436573 runtime.gopark+0x163 /usr/local/gosrc/src/runtime/proc.go:186
# 0x436634 runtime.goparkunlock+0x54 /usr/local/gosrc/src/runtime/proc.go:191
# 0x42051b runtime.backgroundgc+0x8b /usr/local/gosrc/src/runtime/mgc.go:894
4 @ 0x436573 0x421717 0x4669c1
# 0x436573 runtime.gopark+0x163 /usr/local/gosrc/src/runtime/proc.go:186
# 0x421717 runtime.gcBgMarkWorker+0xf7 /usr/local/gosrc/src/runtime/mgc.go:1283
4584 is the PID of the application. cat /proc/4584/status
Name: android
State: S (sleeping)
Tgid: 4584
Ngid: 0
Pid: 4584
PPid: 2776
TracerPid: 0
Uid: 0 0 0 0
Gid: 0 0 0 0
FDSize: 256
Groups: 0
NStgid: 4584
NSpid: 4584
NSpgid: 4584
NSsid: 2776
VmPeak: 631316 kB
VmSize: 573976 kB
VmLck: 0 kB
VmPin: 0 kB
VmHWM: 30060 kB
VmRSS: 29344 kB
VmData: 487492 kB
VmStk: 136 kB
VmExe: 6704 kB
VmLib: 13404 kB
VmPTE: 288 kB
VmPMD: 20 kB
VmSwap: 0 kB
Threads: 10
SigQ: 3/62942
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000000000
SigCgt: ffffffffffc1feff
CapInh: 0000000000000000
CapPrm: 0000003fffffffff
CapEff: 0000003fffffffff
CapBnd: 0000003fffffffff
Seccomp: 0
Cpus_allowed: f
Cpus_allowed_list: 0-3
Mems_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list: 0
voluntary_ctxt_switches: 531158
nonvoluntary_ctxt_switches: 13254
Answer
Bradfitz does a great talk on how to profile go programs using tools such as pprof.
https://www.youtube.com/watch?v=xxDZuPEgbBU&feature=youtu.be
Here's the info from the talk on his github:
https://github.com/bradfitz/talk-yapc-asia-2015/blob/master/talk.md
Hope that helps!