cmd/pprof: list command only respecting no inlining output

[ardan-bkennedy]

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

$ go version
go version devel +f922cc6 Thu Oct 24 17:40:35 2019 +0000 darwin/amd64

Does this issue reproduce with the latest release?

With 1.13 and tip

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/bill/Library/Caches/go-build"
GOENV="/Users/bill/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/bill/code/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/bill/sdk/gotip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/bill/sdk/gotip/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/bill/code/go/src/github.com/ardanlabs/gotraining/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/f8/nl6gsnzs1m7530bkx9ct8rzc0000gn/T/go-build771861905=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

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

I ran the following command

$ gotip test -bench . -benchtime 3s -benchmem -memprofile p.out -gcflags -m=2
$ gotip tool pprof p.out

What did you expect to see?

Type: alloc_space
Time: Oct 24, 2019 at 4:20pm (EDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list algOne
Total: 160.01MB
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
      20MB   160.01MB (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.
  140.01MB   140.01MB     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.
      20MB       20MB     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])
(pprof)

What did you see instead?

Type: alloc_space
Time: Oct 24, 2019 at 4:20pm (EDT)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list algOne
Total: 160.01MB
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
      20MB   160.01MB (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.
         .   140.01MB     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.
      20MB       20MB     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])
(pprof)

Why?

The list command only shows output not taking into account the inling optimization. I need to see the list output with inlining. There is a command flag called -noinlines but that doesn't help me since it is the default mode.

I have reported this several times in the past. There has been some discussion about flags. I think this has been lost. I could not find any open issue related to this.

[dmitshur]

/cc @hyangah per owners.

[ardan-bkennedy]

On tip today I noticed the weblist view was taking into account inlining. This was great to see. The console list command was not.

Not sure this was intended or not?

[hyangah]

We fixed inlined function info encoding in the generated profile data recently. I expected that fixed this bug (but left this open to verify before closing) but, based on your lat comment, I guess something is still broken. What do you mean by the console list command? This is what I got now.

$ go tool pprof p.out
File: memcpu.test
Type: alloc_space
Time: Nov 12, 2019 at 10:23pm (EST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) list lgOne
Total: 127.01MB
ROUTINE ======================== github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne in /tmp/gotraining/topics/go/profiling/memcpu/stream.go
      13MB   127.01MB (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.
         .   114.01MB     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.
      13MB       13MB     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])

[ardan-bkennedy]

The allocation on line 83 should be flat. Now on tip when using weblist it does show as flat.

[ardan-bkennedy]

File: memcpu.test
Type: alloc_space
Time: Nov 12, 2019 at 4:18pm (PST)
Total: 143.51MB
github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne
/Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go

  Total:    143.51MB   143.51MB (flat, cum)   100%
     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     130.01MB   130.01MB           	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. 
     89      13.50MB    13.50MB           	buf := make([]byte, size) 
     90            .          .           	end := size - 1 

[hyangah]

can you try the noinlines option?
I don't know why weblist takes the different default - I think we had a similar discussion but I am confused by so many options :-( google/pprof#415

(pprof) noinlines
(pprof) list algOne
Total: 127.01MB
ROUTINE ======================== github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne in /tmp/gotraining/topics/go/profiling/memcpu/stream.go
  127.01MB   127.01MB (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.
  114.01MB   114.01MB     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.
      13MB       13MB     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])

[ardan-bkennedy]

I will try but this is confusing. It's a flat allocation because of inlining. Using the -noinlines flag to see inlining seems odd?

Using the -noinlines switch is giving me the view with the inlining being taken into account. Which is great! At least I can now turn that on when I want to see the inlining optimization represented!

[hyangah]

Is it ok to close this bug?

ps. reading the referenced google/pprof bug, we had the exactly same discussion about the difference between weblist and list.

[ardan-bkennedy]

Yes. THANK YOU for making this switch toggle the two different views. I really appreciate the effort.

But we aware that list and weblist are working differently. Seems weblist is correct in that the default is inlines where the default in list is nolines. This switch seems to just toggle things.

[randall77]

The correct answer for the bytes.NewBuffer call is 0 flat, 114MB cum. The allocation is *inside* bytes.NewBuffer. (In contrast to what we show today, which is IMO wrong.) The intent of all of these inlining fixes is to make it so the output doesn't depend on whether inlining happened or not. It should appear as you read the source. You should see the 114MB flat line if you list bytes.NewBuffer.

…

On Tue, Nov 12, 2019 at 8:04 PM William Kennedy ***@***.***> wrote: I will try but this is confusing. It's a flat allocation because of inlining. Using the -noinlines flag to see inlining seems odd? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#35143?email_source=notifications&email_token=ABUSAIBMGMSEN64IHYXZEO3QTN4DXA5CNFSM4JE2XAFKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOED4ZU4A#issuecomment-553228912>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ABUSAIE4L3ETSTZLJGIL343QTN4DXANCNFSM4JE2XAFA> .

[ardan-bkennedy]

@randall77 The allocation is caused by the lines calling into io.ReadFull. The escape analysis report will show line 113 as the cause.

If the inlining optimization is taken into account, then line 113 is the cause. If the inline optimization does not take place, then it is line 83.

if I am trying to remove this allocation I need to deal with the io.Read calls, not the call to NewBuffer.

[hyangah]

Before closing this bug, I want to clarify:

@ardan-bkennedy We didn't make any pprof command line tool change. The pprof command line tool features are maintained by the upstream pprof team. We fixed a bug in runtime/pprof that caused missing inline info in generated profiles (regression undetected in the last couple of release cycles). For pprof feature improvement requests, please file requests to upstream.

@randall77 We still show 0 flat, 114MB cum by default - which I also think more appropriate as the default. list command is supposed to show the source line level truth by default. Power-users who want to optimize their application based on a specific version of Go and the specific set of build flags may choose to look into the inline info by providing extra options.