runtime/pprof(?): CPU profile only covers 1% of time

[cherrymui]

What version of Go are you using (go version)?

tip (16db189)

What operating system and processor architecture are you using (go env)?

linux/amd64

What did you do?

$ go test -c math
$ ./math.test -test.bench=Lgamma -test.benchtime=10s -test.cpuprofile=/tmp/p
...
$ go tool pprof math.test /tmp/p
File: math.test
Type: cpu
Time: Apr 17, 2017 at 4:37pm (EDT)
Duration: 21.52s, Total samples = 214.20ms (    1%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 214.10ms, 100% of 214.20ms total
Dropped 4 nodes (cum <= 1.07ms)
      flat  flat%   sum%        cum   cum%
  197.10ms 92.02% 92.02%   197.10ms 92.02%  math.Lgamma
    9.40ms  4.39% 96.41%   214.10ms   100%  math_test.BenchmarkLgamma
    7.60ms  3.55%   100%     7.60ms  3.55%  math.Lgamma
         0     0%   100%   214.10ms   100%  testing.(*B).launch
         0     0%   100%   214.10ms   100%  testing.(*B).runN
(pprof)

Note that the profile only covers 1%: Duration: 21.52s, Total samples = 214.20ms ( 1%).

This is not the case for Go 1.8.

$ go1.8 test -c math
$ ./math.test -test.bench=Lgamma -test.benchtime=10s -test.cpuprofile=/tmp/p18
$ go tool pprof math.test /tmp/p18
File: math.test
Type: cpu
Time: Apr 17, 2017 at 4:39pm (EDT)
Duration: 21.26s, Total samples = 21.27s (100.06%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 21270ms, 100% of 21270ms total
      flat  flat%   sum%        cum   cum%
   20560ms 96.66% 96.66%    20560ms 96.66%  math.Lgamma
     710ms  3.34%   100%    21270ms   100%  math_test.BenchmarkLgamma
         0     0%   100%    21270ms   100%  runtime.goexit
         0     0%   100%    21270ms   100%  testing.(*B).launch
         0     0%   100%    21270ms   100%  testing.(*B).runN
(pprof) 

Given the default profiling rate is 100, maybe a factor of 100 is missing somewhere?

[ALTree]

I remember bcmills being confused by the new way to show samples (see #19563 (comment)) and he opened google/pprof#128.

[bcmills]

It sounds like pprof displays the samples in whatever units are set in the protobuf. Perhaps we could change Go's pprof package to use more sensible units?

[cherrymui]

I'm not sure how other languages write profile. For a C++ program running 22 seconds, it does show a coverage about 22 seconds:

(pprof) top
Showing nodes accounting for 18580ms, 83.54% of 22240ms total

Does C++ profile use a different unit?

[aclements]

Fixed by 0c0c94a.