Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

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
like image 464
Anthony Hunt Avatar asked Aug 18 '15 16:08

Anthony Hunt


1 Answers

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!

like image 130
Dustin Avatar answered Nov 12 '22 19:11

Dustin