Navigation Menu

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

Jump to bottom

cmd/pprof: list comment added extra noise in 1.9beta2 #21023

Closed
ardan-bkennedy opened this issue Jul 15, 2017 · 7 comments
Closed

cmd/pprof: list comment added extra noise in 1.9beta2 #21023

ardan-bkennedy opened this issue Jul 15, 2017 · 7 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker
Milestone
Go1.10

Comments

@ardan-bkennedy
Copy link

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

go version go1.9beta2 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/bill/code/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_v/4r515ktx08g5yr6dgkxhfyfr0000gn/T/go-build016620058=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

Code to reproduce the bug?

https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/memcpu

What did you do?

$ go test -run none -bench . -benchtime 3s -memprofile mem.out
$ go tool pprof -alloc_space memcpu.test mem.out
(pprof) list algOne

File: memcpu.test
Type: alloc_space
Time: Jul 15, 2017 at 11:40am (MDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list algOne
Total: 354.04MB
ROUTINE ======================== github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne in /Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go
  354.04MB   354.04MB (flat, cum)   100% of Total
         .          .      8:// The solution cannot meaningfully buffer to the end of the stream and
         .          .      9:// then process the replacement.
         .          .     10:package main
         .          .     11:
         .          .     12:import (
  338.04MB   338.04MB     13:	"bytes"
         .          .     14:	"fmt"
         .          .     15:	"io"
         .          .     16:)
         .          .     17:
         .          .     18:// data represents a table of input and expected output.
         .          .     19:var data = []struct {
         .          .     20:	input  []byte
         .          .     21:	output []byte
         .          .     22:}{
         .          .     23:	{[]byte("abc"), []byte("abc")},
         .          .     24:	{[]byte("elvis"), []byte("Elvis")},
         .          .     25:	{[]byte("aElvis"), []byte("aElvis")},
         .          .     26:	{[]byte("abcelvis"), []byte("abcElvis")},
         .          .     27:	{[]byte("eelvis"), []byte("eElvis")},
         .          .     28:	{[]byte("aelvis"), []byte("aElvis")},
         .          .     29:	{[]byte("aabeeeelvis"), []byte("aabeeeElvis")},
         .          .     30:	{[]byte("e l v i s"), []byte("e l v i s")},
         .          .     31:	{[]byte("aa bb e l v i saa"), []byte("aa bb e l v i saa")},
         .          .     32:	{[]byte(" elvi s"), []byte(" elvi s")},
         .          .     33:	{[]byte("elvielvis"), []byte("elviElvis")},
         .          .     34:	{[]byte("elvielvielviselvi1"), []byte("elvielviElviselvi1")},
         .          .     35:	{[]byte("elvielviselvis"), []byte("elviElvisElvis")},
         .          .     36:}
         .          .     37:
         .          .     38:// assembleInputStream combines all the input into a
         .          .     39:// single stream for processing.
         .          .     40:func assembleInputStream() []byte {
         .          .     41:	var in []byte
         .          .     42:	for _, d := range data {
         .          .     43:		in = append(in, d.input...)
         .          .     44:	}
         .          .     45:	return in
         .          .     46:}
         .          .     47:
         .          .     48:// assembleOutputStream combines all the output into a
         .          .     49:// single stream for comparing.
         .          .     50:func assembleOutputStream() []byte {
         .          .     51:	var out []byte
         .          .     52:	for _, d := range data {
         .          .     53:		out = append(out, d.output...)
         .          .     54:	}
         .          .     55:	return out
         .          .     56:}
         .          .     57:
         .          .     58:func main() {
         .          .     59:	var output bytes.Buffer
         .          .     60:	in := assembleInputStream()
         .          .     61:	out := assembleOutputStream()
         .          .     62:
         .          .     63:	find := []byte("elvis")
         .          .     64:	repl := []byte("Elvis")
         .          .     65:
         .          .     66:	fmt.Println("=======================================\nRunning Algorithm One")
         .          .     67:	output.Reset()
         .          .     68:	algOne(in, find, repl, &output)
         .          .     69:	matched := bytes.Compare(out, output.Bytes())
         .          .     70:	fmt.Printf("Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes())
         .          .     71:
         .          .     72:	fmt.Println("=======================================\nRunning Algorithm Two")
         .          .     73:	output.Reset()
         .          .     74:	algTwo(in, find, repl, &output)
         .          .     75:	matched = bytes.Compare(out, output.Bytes())
         .          .     76:	fmt.Printf("Matched: %v\nInp: [%s]\nExp: [%s]\nGot: [%s]\n", matched == 0, in, out, output.Bytes())
         .          .     77:}
         .          .     78:
         .          .     79:// algOne is one way to solve the problem.
         .          .     80:func algOne(data []byte, find []byte, repl []byte, output *bytes.Buffer) {
         .          .     81:
         .          .     82:	// Use a bytes Buffer to provide a stream to process.
         .          .     83:	input := bytes.NewBuffer(data)
         .          .     84:
         .          .     85:	// The number of bytes we are looking for.
         .          .     86:	size := len(find)
         .          .     87:
         .          .     88:	// Declare the buffers we need to process the stream.
      16MB       16MB     89:	buf := make([]byte, size)
         .          .     90:	end := size - 1
         .          .     91:
         .          .     92:	// Read in an initial number of bytes we need to get started.
         .          .     93:	if n, err := io.ReadFull(input, buf[:end]); err != nil {
         .          .     94:		output.Write(buf[:n])

What did I expect?

Total: 339.03MB
ROUTINE ======================== github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne in /Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go
  339.03MB   339.03MB (flat, cum)   100% of Total
         .          .     78:
         .          .     79:// algOne is one way to solve the problem.
         .          .     80:func algOne(data []byte, find []byte, repl []byte, output *bytes.Buffer) {
         .          .     81:
         .          .     82:	// Use a bytes Buffer to provide a stream to process.
  325.03MB   325.03MB     83:	input := bytes.NewBuffer(data)
         .          .     84:
         .          .     85:	// The number of bytes we are looking for.
         .          .     86:	size := len(find)
         .          .     87:
         .          .     88:	// Declare the buffers we need to process the stream.
      14MB       14MB     89:	buf := make([]byte, size)
         .          .     90:	end := size - 1
         .          .     91:
         .          .     92:	// Read in an initial number of bytes we need to get started.
         .          .     93:	if n, err := io.ReadFull(input, buf[:end]); err != nil {
         .          .     94:		output.Write(buf[:n])

The new list command is not isolating itself to just the function that matches the regular expression. Showing all the code is a lot of noise.

Also

ROUTINE ========================
github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne in
/Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go

Showing the source code file is nice but the entire path being listed twice is noise. This would have been better.

ROUTINE ========================
memcpu.algOne in github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go
@ianlancetaylor ianlancetaylor changed the title pprof list comment added extra noise in 1.9beta2 cmd/pprof: list comment added extra noise in 1.9beta2 Jul 15, 2017
@ianlancetaylor
Copy link
Contributor

CC @matloob

@ianlancetaylor ianlancetaylor added this to the Go1.10 milestone Jul 15, 2017
@matloob
Copy link
Contributor

matloob commented Jul 15, 2017

CC @rauls5382
I wonder if this may have been caused by the last cmd/pprof import from github.com/google/pprof in 7844ef

@vcabbage
Copy link
Member

Interestingly, the output displays as expected if the test binary isn't provided to pprof.

@ALTree ALTree mentioned this issue Jul 16, 2017
Closed
@ALTree
Copy link
Member

ALTree commented Jul 16, 2017 •
edited

Another data point: this may be a Darwin-specific issue, because I can't reproduce this on my Linux machine. I don't have a Windows machine to test.

Same for #21022 (cannot reproduce on Linux).

@ALTree ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jul 16, 2017
@rauls5382
Copy link
Contributor

rauls5382 commented Jul 18, 2017 •
edited

This problem is related to poor offline symbolization in Darwin.

The reason pprof shows the whole file is because there are samples associated to line 13 (see the 338Mb on the bad output listed above). pprof will print the lines around the samples associated to algOne (between lines 13 and 89 in this file).

The Go runtime generates correct symbolized profiles, which is why the problem goes away when the binary isn't specified in the command line. But Go doesn't tag the mappings as fully symbolized, so pprof will attempt to resymbolize them if given a chance (see google/pprof#147 for some relevant discussion).

When the binary is specified on the command line, pprof will resymbolize using that binary, and it gets some mangled line numbers in Darwin when dealing with inline functions.

Some experiments:

  • With the golang online symbolization (GOOD):
     5: 0x10ef270 bytes.NewBuffer /Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go:13 s=0
             _/Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne /Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go:83 s=0
  • When symbolizing offline using the binary (BAD):
     5: 0x10ef270 M=1 _/Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne /Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go:13 s=0

Note how in the bad case we have a single frame with the function name and the filename of olgOne, but the line number that should correspond to bytes.NewBuffer.

I would recommend:

  1. Have the Go runtime set the has_bits more accurately (it does require some effort to handle mixed-language binaries correctly, as discussed in profile: Support merge of slightly different but similar Profiles. google/pprof#147 ).
  2. Look into why the symbolization code for Darwin is creating this frame. It doesn't appear to have support for inline frames, which may be part of the problem. This code is in src/cmd/internal/objfile.

@bradfitz bradfitz marked this as a duplicate of #21022 Jul 20, 2017
@gopherbot
Copy link

CL https://golang.org/cl/50430 mentions this issue.

@rsc
Copy link
Contributor

rsc commented Nov 22, 2017

Now that Go 1.10 symbolizes all profiles, simply never pass the binary to pprof. If any examples show the old two-argument command lines we should update them. If so, please file separate issues.

@rsc rsc closed this as completed Nov 22, 2017
@golang golang locked and limited conversation to collaborators Nov 22, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker
Projects
None yet
Milestone
Go1.10
Development

No branches or pull requests
8 participants
@rsc @ardan-bkennedy @ianlancetaylor @ALTree @gopherbot @vcabbage @rauls5382 @matloob