6

I'm profiling a Go application with pprof.

The application is using about 4-10% CPU and leaving it running for a short while produces a profile of around 6-11kb. This suggests to me that it should be able to sample some activity.

When I view the result, however, I see the following:

$ go tool pprof --text bigproc
1.77s of 1.77s total (  100%)
      flat  flat%   sum%        cum   cum%
     1.77s   100%   100%      1.77s   100%
$

The interesting information appears to be missing. What could be wrong?

This is on linux, with go version 1.6.1 and pprof version 2.2.1 of google-perftools (if that matters).

AkiRoss
  • 11,745
  • 6
  • 59
  • 86
Arnout Engelen
  • 6,709
  • 1
  • 25
  • 36
  • 1
    You're going to have to sample for a lot longer that 1.7 sec, especially at only 4-10% cpu. Try sampling for a few minutes. – JimB May 21 '16 at 22:13
  • I ran the process for something like a minute wall-clock time. I'm guessing the 1.77 seconds mentioned in the output are CPU time, so excluding the time that the CPU was idle (program being blocked or sleeping). I'll try running longer though! – Arnout Engelen May 21 '16 at 22:25
  • 1
    Normally when you profile you stress the code path that you're profiling to get as many samples as possible from there, rather than an idle runtime. If you're only using 4-10% cpu, 90-96% of your samples won't be any good. – JimB May 21 '16 at 22:50
  • Certainly that's the next step, but first I need to identify what part of the code needs improvement. Of course I can make an educated guess, but it'd be great if a profiler could validate that theory before going further. – Arnout Engelen May 21 '16 at 22:55
  • The reason of the issue are elsewhere, but you should try to increase the sampling time anyway, for example, performing the same task in a loop a few times. – AkiRoss May 22 '16 at 03:24

2 Answers2

5

You are mis-using the go tool pprof, because you shall specify the executable file associated with the generated profile.

Compare this

$ go tool pprof --text cpuprofile.prof
680ms of 680ms total (  100%)
      flat  flat%   sum%        cum   cum%
     680ms   100%   100%      680ms   100%

with this (note main, that is the executable that produced the cpuprofile.prof)

$ go tool pprof --text main cpuprofile.prof
680ms of 680ms total (  100%)
      flat  flat%   sum%        cum   cum%
     350ms 51.47% 51.47%      610ms 89.71%  main.renderMandelbrotUnified
     130ms 19.12% 70.59%      130ms 19.12%  math.Log
      40ms  5.88% 76.47%       60ms  8.82%  image.(*RGBA).Set
[cut]

It's not a matter of wrong sampling: consider that around 100 samples are taken every second of execution, so even of 1.7s you should get some samples anyway (from here):

When CPU profiling is enabled, the Go program stops about 100 times per second and records a sample consisting of the program counters on the currently executing goroutine's stack

AkiRoss
  • 11,745
  • 6
  • 59
  • 86
  • Thanks, I feel so stupid! I take some comfort in the fact that I'm not alone: https://github.com/golang/go/issues/10863 :) – Arnout Engelen May 22 '16 at 08:02
  • Yes don't worry, happened to me as well and I was lucky enough to notice it before posting on SO! :D – AkiRoss May 22 '16 at 11:07
  • 1
    Hopefully https://go-review.googlesource.com#/c/23323/ will make it through in some form or other, so we'll save future generations this confusion – Arnout Engelen May 22 '16 at 11:14
-1

Sometimes this problem appears when your programs completes execution too fast. Watch out!

Romanov Saveliy
  • 21
  • 3