runtime: pprof list command not showing allocation in 1.9beta2 #21022

ardan-bkennedy · 2017-07-15T17:49:28Z

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

         .          .     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) <---- MISSING ALLOCATION
         .          .     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])

The allocation for input is not being reported in pprof but the escape analysis does confirm the escape.

$ go build -gcflags "-m -m"

./stream.go:83:26: inlining call to bytes.NewBuffer func([]byte) *bytes.Buffer { return &bytes.Buffer literal }

./stream.go:83:26: &bytes.Buffer literal escapes to heap
./stream.go:83:26: 	from ~r0 (assign-pair) at ./stream.go:83:26
./stream.go:83:26: 	from input (assigned) at ./stream.go:83:8
./stream.go:83:26: 	from input (interface-converted) at ./stream.go:93:26
./stream.go:83:26: 	from input (passed to call[argument escapes]) at ./stream.go:93:26

What did you expect to see?

go1.8.3 darwin/amd64

         .          .     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) <---- ALLOCATION REPORTED
         .          .     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])

I have highlighted the line in the report for 1.8 where pprof shows input escaping to the heap. The escape analysis report also shows these allocations.

$ go build -gcflags "-m -m"

./stream.go:83: inlining call to bytes.NewBuffer func([]byte) *bytes.Buffer { return &bytes.Buffer literal }

./stream.go:83: &bytes.Buffer literal escapes to heap
./stream.go:83: 	from ~r0 (assign-pair) at ./stream.go:83
./stream.go:83: 	from input (assigned) at ./stream.go:83
./stream.go:83: 	from input (interface-converted) at ./stream.go:93
./stream.go:83: 	from input (passed to call[argument escapes]) at ./stream.go:93

What did you see instead?

In the 1.9 beta this particular allocation of the input value is not showing up on the pprof list call.

The text was updated successfully, but these errors were encountered:

ALTree · 2017-07-16T17:02:44Z

There must be something wrong with Darwin, because I can't reproduce this (nor #21023) on my Linux machine.

$ gotip version
go version devel +dd81c37f91 Sat Jul 15 05:43:45 2017 +0000 linux/amd64

$ gotip tool pprof -alloc_space memcpu.test mem.out
File: memcpu.test
Type: alloc_space
Time: Jul 16, 2017 at 6:59pm (CEST)
Entering interactive mode (type "help" for commands, "o" for options)

(pprof)  list algOne
Total: 105.01MB
ROUTINE ======================== _/home/alberto/Desktop/gotraining/topics/go/profiling/memcpu.algOne in /home/alberto/Desktop/gotraining/topics/go/profiling/memcpu/stream.go
  105.01MB   105.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.
  100.51MB   100.51MB     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.
    4.50MB     4.50MB     89:	buf := make([]byte, size)

ALTree · 2017-07-16T17:08:28Z

@ardan-bkennedy which Darwin version are you using?

ardan-bkennedy · 2017-07-16T18:21:20Z

macOS Sierra 10.12.5

ALTree · 2017-07-17T08:22:19Z

Thanks. I know about 10.10 issues (I opened an issue upstream because we were seeing builders failures in the pprof test suite) but since you're using 10.12 this could be something different.

See and google/pprof#146 and google/pprof#156 (comment)

rauls5382 · 2017-07-18T01:59:50Z

This is the same problem as #21023. I've validated that it works fine if the binary is not specified in the command line:

(pprof) rsilvera-macbookpro:memcpu rsilvera$ go tool pprof -alloc_space  mem.out
Entering interactive mode (type "help" for commands)
(pprof) list algOne
Total: 337.53MB
ROUTINE ======================== _/Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu.algOne in /Users/rsilvera/github.com/ardanlabs/gotraining/topics/go/profiling/memcpu/stream.go
      14MB   337.53MB (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.
         .   323.53MB     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])
(pprof)

bradfitz · 2017-07-20T19:10:23Z

Duplicate of #21023.

Okay, closing. The release notes do say:

Profiles produced by the runtime/pprof package now include symbol information, so they can be viewed in go tool pprof without the binary that produced the profile.

Maybe that should be amended to say "should" for now?

@ianlancetaylor?

ianlancetaylor · 2017-07-20T19:15:03Z

Sorry, I don't really know.

CC @matloob @rauls5382

rauls5382 · 2017-07-20T19:33:46Z

I agree the documentation should encourage the use of pprof without using the binary.
It is a bit more nuanced, though: the binary is needed to symbolize non-Go symbols (eg C++).

gopherbot · 2017-07-27T04:22:44Z

Change https://golang.org/cl/50430 mentions this issue: doc: mention need to omit binary name from go tool pprof sometimes

ianlancetaylor changed the title ~~pprof list command not showing allocation in 1.9beta2~~ runtime: pprof list command not showing allocation in 1.9beta2 Jul 15, 2017

ianlancetaylor added the NeedsInvestigation label Jul 15, 2017

ianlancetaylor added this to the Go1.9Maybe milestone Jul 15, 2017

ALTree mentioned this issue Jul 16, 2017

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

Closed

bradfitz marked this as a duplicate of #21023 Jul 20, 2017

bradfitz closed this as completed Jul 20, 2017

golang locked and limited conversation to collaborators Aug 30, 2018

gopherbot added the FrozenDueToAge label Aug 30, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

runtime: pprof list command not showing allocation in 1.9beta2 #21022

runtime: pprof list command not showing allocation in 1.9beta2 #21022

ardan-bkennedy commented Jul 15, 2017

ALTree commented Jul 16, 2017 •

edited

Loading

ALTree commented Jul 16, 2017

ardan-bkennedy commented Jul 16, 2017

ALTree commented Jul 17, 2017 •

edited

Loading

rauls5382 commented Jul 18, 2017 •

edited

Loading

bradfitz commented Jul 20, 2017

ianlancetaylor commented Jul 20, 2017

rauls5382 commented Jul 20, 2017

gopherbot commented Jul 27, 2017

runtime: pprof list command not showing allocation in 1.9beta2 #21022

runtime: pprof list command not showing allocation in 1.9beta2 #21022

Comments

ardan-bkennedy commented Jul 15, 2017

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

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

Code to reproduce the bug?

What did you do?

What did you expect to see?

What did you see instead?

ALTree commented Jul 16, 2017 • edited Loading

ALTree commented Jul 16, 2017

ardan-bkennedy commented Jul 16, 2017

ALTree commented Jul 17, 2017 • edited Loading

rauls5382 commented Jul 18, 2017 • edited Loading

bradfitz commented Jul 20, 2017

ianlancetaylor commented Jul 20, 2017

rauls5382 commented Jul 20, 2017

gopherbot commented Jul 27, 2017

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

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

ALTree commented Jul 16, 2017 •

edited

Loading

ALTree commented Jul 17, 2017 •

edited

Loading

rauls5382 commented Jul 18, 2017 •

edited

Loading