cmd/pprof: header size >= 2**16

[gopherbot]

by baron@xaprb.com:

Using go 1.2, I found the same issue reported in an old mailing list thread,
https://groups.google.com/d/topic/golang-nuts/LFk2-ikvxTs/discussion: "go tool
pprof" reports header size >= 2**16. The problem is an extra three-dash line in
the input.

I reproduced this with the following program: http://play.golang.org/p/oUJCQPRzWL

Then I ran the following commands:

$ go tool pprof --raw http://localhost:6060/debug/pprof/heap > local.raw
Read http://localhost:6060/debug/pprof/symbol
Fetching /pprof/heap profile from localhost:6060 to
  /var/folders/4s/jyvtqxm91k5bk1cyrqx8thlr0000gn/T/EiHLDyUj3i
Wrote profile to /var/folders/4s/jyvtqxm91k5bk1cyrqx8thlr0000gn/T/EiHLDyUj3i
Adjusting heap profiles for 1-in-524288 sampling rate
$ go tool pprof --text local.raw
local.raw: header size >= 2**16

[pnasrat]

Comment 1:

The pprof fork seems to be in misc/pprof
https://code.google.com/p/go/source/browse/misc/pprof 
PrintSymbolizedProfile is what outputs the extra '---'
raw was introduced in 1.4 by the looks, including that line
https://code.google.com/p/gperftools/source/detail?r=19dfa9e3733155e57406fbd082273eb53cb2750e&name=19dfa9e3

[pnasrat]

Comment 2:

Looking at this, there are a few issues here with the interaction of FixCallerAddress
and the fact raw is a symbolized profile. Just removing the line with --- from the heap
works but we don't get symbols resolved
go tool  pprof --text --alloc_space  ~/go/src/github.com/dotcloud/docker/heap  | head
Adjusting heap profiles for 1-in-524288 sampling rate
Total: 760.5 MB
   408.0  53.6%  53.6%    408.0  53.6% 0x0000000000428771
   255.0  33.5%  87.2%    255.0  33.5% 0x000000000042b565
    88.0  11.6%  98.8%     88.0  11.6% 0x00000000004286a2
     5.5   0.7%  99.5%      5.5   0.7% 0x00000000004143f1
     3.0   0.4%  99.9%      3.0   0.4% 0x000000000042bc69
     0.5   0.1%  99.9%      0.5   0.1% 0x00000000004143c7
     0.5   0.1% 100.0%      0.5   0.1% 0x0000000000428668
     0.0   0.0% 100.0%      0.5   0.1% 0x00000000004073c0
     0.0   0.0% 100.0%      8.0   1.1% 0x000000000040ee11
Hacking pprof to do the subtraction 
perl  pprof --text --alloc_space  ~/go/src/github.com/dotcloud/docker/heap  | head
Adjusting heap profiles for 1-in-524288 sampling rate
Total: 760.5 MB
   166.0  21.8%  21.8%    180.5  23.7% github.com/dotcloud/docker/graphdriver/aufs.getParentIds
   146.5  19.3%  41.1%    149.5  19.7% github.com/dotcloud/docker/utils.(*TruncIndex).lookup
    94.0  12.4%  53.5%     94.0  12.4% io/ioutil.readAll
    57.0   7.5%  60.9%     57.0   7.5% strings.Join
    26.5   3.5%  64.4%     27.5   3.6% io.Copy
    26.0   3.4%  67.9%     35.5   4.7% encoding/json.(*decodeState).literalStore
    25.5   3.4%  71.2%     25.5   3.4% encoding/json.unquote
    22.0   2.9%  74.1%     22.0   2.9% syscall.ByteSliceFromString
    21.0   2.8%  76.9%     21.0   2.8% index/suffixarray.initGroups

[gopherbot]

Comment 3 by baron@xaprb.com:

I noticed that in some kinds of profiling, there are extra --- lines, and
in other kinds there are not extra lines and the tools work ok without
modifying the raw output.

[davecheney]

Comment 4:

@pnasrst, go tool pprof takes at a minimum two arguments
go tool pprof $BIN $PROF...
Bin must be exactly the binary that produces the profile, there may be more than one
profile file produced

[pnasrat]

Comment 5:

Dave - note that pprof support two modes with a profile. The common mode as you mention,
where you need the binary for symbols, and the raw mode which outputs a symbolized
profile/heap, this avoids having to have the exact binary around (useful for bug
reporting, etc).
go tool pprof --raw http://localhost:6060/debug/pprof/heap
Read http://localhost:6060/debug/pprof/symbol
Fetching /pprof/heap profile from localhost:6060 to
  /tmp/6QVfEKcwS_
Wrote profile to /tmp/6QVfEKcwS_
Adjusting heap profiles for 1-in-524288 sampling rate
--- symbol
binary=./pprofd
---
--- profile
heap profile: 1: 288 [2: 296] @ heap/1048576
1: 288 [2: 296] @
This bug is about the output with --raw not working with the parsing for raw, but there
are multiple bugs not just the output rendering. 
Note if you do as you suggest pprof errors. 
mkdir /tmp/pprofd;  cd /tmp/pprofd
curl http://play.golang.org/p/oUJCQPRzWL.go > pprofd.go
go build
./pprofd
In another terminal, caputure a heap:
go tool pprof --raw http://localhost:6060/debug/pprof/heap > /tmp/heap
Your method won't work on symbolized heaps:
go tool pprof --text  ./pprofd /tmp/heap 
FATAL ERROR: Symbolized profile '/tmp/heap' cannot be used with a binary arg.  Try again
without passing './pprofd'.
Options are - fix pprof --raw as per the help examples:
pprof --raw localhost:1234 > ./local.raw
pprof --text ./local.raw
                       Fetches a remote profile for later analysis and then
                       analyzes it in text mode.
Options to fix are - remove --raw from the go fork of pprof or fix it - which shouldn't
be too hard, but you want to make sure that FixCallerAddress with raw symbolized
profiles does the right thing. I'm happy to take a stab at either.

[pnasrat]

Comment 6:

Another option would be to rewrite the go tool pprof in go with more tests, etc. Again
happy to take that approach if it's deemed worth the effort.

[gopherbot]

Comment 7 by baron@xaprb.com:

I think it would be great to move away from Perl, although I don't think
the Perl in this tool is too bad actually. But I wonder if the original
"upstream" maintainers would have any input on it. Maybe they'd rather see
some redesign or something instead of a straight Perl->Go rewrite.

[davecheney]

Comment 8:

I'm going to mark this issue as Thinking. I'm pretty sure there is general agreement
that rewriting the current pprof in Go would be a good idea, but it is a non trivial
amount of work and is not on anyone's radar at the moment.

Labels changed: added release-none, repo-main.

Status changed to Thinking.

[bradfitz]

Comment 9:

People inside Google rewrote this Perl pprof script in Go. I think the plan is (and was)
to open source it now, and Go to use the same one.
I don't know what the status is (or even if the Go rewrite is complete). It seems to
exist, though.

[rakyll]

Comment 10:

Go rewrite of that script seems to be open sourced.
https://golang.org/cl/153750043

[bradfitz]

Comment 11:

This is likely fixed. Can the OP or somebody confirm, if they could previously reproduce
the bug?

Status changed to WaitingForReply.

[pnasrat]

Comment 12:

I've only looked at this briefly - but wanted to respond before I go on vacation, I'm
not sure we're quite there
go version
go version devel +7e89fedb40e6 Tue Oct 21 13:26:40 2014 +0200 linux/amd64
I need to look in some more detail though - I'm seeing some issues with go tool pprof
(old) vs running the binary pprof directly using godoc and running ab in the background
against it
 go tool pprof --raw  http://localhost:6060/debug/pprof/profile  > /tmp/profile.raw
Possible precedence issue with control flow operator at
/usr/src/go/pkg/tool/linux_amd64/pprof line 3014.
Read http://localhost:6060/debug/pprof/symbol
Gathering CPU profile from http://localhost:6060/debug/pprof/profile?seconds=30 for 30
seconds to
  /tmp/uqzfHV5A7S
root@85a3e81044dc://usr/src/go# go tool pprof /tmp/profile.raw 
Possible precedence issue with control flow operator at
/usr/src/go/pkg/tool/linux_amd64/pprof line 3014.
Welcome to pprof!  For help, type 'help'.
(pprof) top
Total: 1990 samples
     599  30.1%  30.1%      599  30.1% syscall.Syscall
     120   6.0%  36.1%      120   6.0% scanblock
      71   3.6%  39.7%       71   3.6% runtime.MSpan_Sweep
      54   2.7%  42.4%       54   2.7% runtime.readvarint
      51   2.6%  45.0%       51   2.6% runtime.mallocgc
      45   2.3%  47.2%       45   2.3% runtime.memmove
      38   1.9%  49.1%       38   1.9% adjustpointers
      38   1.9%  51.1%       38   1.9% runtime.findfunc
      36   1.8%  52.9%       36   1.8% runtime.step
      31   1.6%  54.4%       31   1.6% syscall.Syscall6
(pprof) 
./bin/pprof /tmp/profile.raw 
parsing profile: unrecognized profile format
./bin/pprof --raw  http://localhost:6060/debug/pprof/profile  > /tmp/profile.new.raw 
Fetching profile from http://localhost:6060/debug/pprof/profile
Please wait... (30s)
Saved profile in /root/pprof/pprof.localhost:6060.samples.cpu.002.pb.gz
./bin/pprof /tmp/profile.new.raw 
parsing profile: unrecognized profile format
./bin/pprof --text  /root/pprof/pprof.localhost:6060.samples.cpu.002.pb.gz
27.28s of 27.28s total (  100%)
      flat  flat%   sum%        cum   cum%
    27.28s   100%   100%     27.28s   100%  
./bin/pprof --top ./bin/godoc  /root/pprof/pprof.localhost:6060.samples.cpu.002.pb.gz |
head
20.51s of 27.28s total (75.18%)
Dropped 326 nodes (cum <= 0.14s)
Showing top 80 nodes out of 158 (cum >= 0.23s)
      flat  flat%   sum%        cum   cum%
     7.48s 27.42% 27.42%      7.75s 28.41%  syscall.Syscall
     1.88s  6.89% 34.31%      1.88s  6.89%  scanblock
     1.09s  4.00% 38.31%      1.09s  4.00%  runtime.MSpan_Sweep
     0.76s  2.79% 41.09%      0.76s  2.79%  runtime.readvarint
     0.62s  2.27% 43.37%      0.90s  3.30%  runtime.mallocgc
     0.58s  2.13% 45.49%      0.58s  2.13%  runtime.memmove
   
Looking at the legacy parser src/cmd/pprof/internal/profile/legacy_profile.go it doesn't
seem to handle symbolized raw dumps. The new src/cmd/pprof/internal/report/report.go
basically just does?
  case Raw:
    fmt.Fprint(w, rpt.prof.String())
    return nil
From my understanding of it the previous raw command was designed to allow a profile
with the symbols to be captured and shared without needing to share the binary.
I can try make the go pprof support the legacy raw format as input, but as the meaning
of --raw has changed in this version I'm not sure if it's a meaningful flag as we can
save the pb. I'd expect the ability to resolve the symbols at sampling time vi
http://localhost:6060/debug/pprof/symbol - looking at HasFileLines and
src/cmd/pprof/internal/profile/profile.go it looks like the format supports it - I'd
expect the raw format to be the fully populated protobuf with symbols for standalone
analysis not the string representation of the Profile struct.

[pnasrat]

Comment 13:

OK so the way to achieve remote symbolized dump with the new pprof is
pprof --symbolize=remote --proto -output=/tmp/p.pb.gz
http://localhost:6060/debug/pprof/profile     
./bin/pprof --text /tmp/p.pb.gz | head
16.97s of 22.06s total (76.93%)
Dropped 317 nodes (cum <= 0.11s)
      flat  flat%   sum%        cum   cum%
     6.24s 28.29% 28.29%      6.41s 29.06%  syscall.Syscall
     1.21s  5.49% 33.77%      1.21s  5.49%  scanblock
     0.91s  4.13% 37.90%      0.91s  4.13%  runtime.MSpan_Sweep
     0.65s  2.95% 40.84%      0.65s  2.95%  adjustpointers
     0.53s  2.40% 43.25%      0.53s  2.40%  runtime.readvarint
     0.48s  2.18% 45.42%      0.49s  2.22%  runtime.step
     0.46s  2.09% 47.51%      0.46s  2.09%  runtime.memmove
./bin/pprof --symbolize=remote --raw http://localhost:6060/debug/pprof/profile will
create a raw profile with symbols but as previous comment this is not supported as an
input to pprof.
I'd probably argue if you just have a URL to pprof we should default to remote.