Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
gopherbot opened this issue Dec 8, 2013 · 14 comments
Closed

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

gopherbot opened this issue Dec 8, 2013 · 14 comments

Comments

@gopherbot
Copy link

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
Copy link

pnasrat commented Dec 30, 2013

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
Copy link

pnasrat commented Dec 30, 2013

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
Copy link
Author

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
Copy link
Contributor

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
Copy link

pnasrat commented Dec 30, 2013

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
Copy link

pnasrat commented Dec 30, 2013

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
Copy link
Author

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
Copy link
Contributor

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
Copy link
Contributor

bradfitz commented Feb 5, 2014

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
Copy link
Contributor

rakyll commented Oct 21, 2014

Comment 10:

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

@bradfitz
Copy link
Contributor

Comment 11:

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

Status changed to WaitingForReply.

@pnasrat
Copy link

pnasrat commented Oct 24, 2014

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
Copy link

pnasrat commented Oct 24, 2014

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.

@rsc rsc added this to the Unplanned milestone Apr 10, 2015
@mikioh mikioh changed the title go tool pprof: header size >= 2**16 cmd/pprof: header size >= 2**16 Aug 13, 2015
@rsc
Copy link
Contributor

rsc commented Mar 6, 2017

Obsolete. The profiles are not text anymore, and the program isn't a Perl script anymore.

@rsc rsc closed this as completed Mar 6, 2017
@golang golang locked and limited conversation to collaborators Mar 6, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

6 participants