cmd/pprof: disasm not working

[rsc]

On my Mac, if I run go test -cpuprofile=x.prof anything, and then go tool pprof x.prof, then the disasm command in pprof does not work, for any function at all:

% go test -cpuprofile=x.prof strings
ok  	strings	1.059s
% go tool pprof x.prof
Type: cpu
Time: Jan 28, 2022 at 2:06pm (EST)
Duration: 805.01ms, Total samples = 540ms (67.08%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 540ms, 100% of 540ms total
Showing top 10 nodes out of 27
      flat  flat%   sum%        cum   cum%
     210ms 38.89% 38.89%      210ms 38.89%  cmpbody
     170ms 31.48% 70.37%      170ms 31.48%  memeqbody
      50ms  9.26% 79.63%       50ms  9.26%  unicode.to
      50ms  9.26% 88.89%       50ms  9.26%  unicode/utf8.EncodeRune
      30ms  5.56% 94.44%      140ms 25.93%  strings.Map
      10ms  1.85% 96.30%       10ms  1.85%  runtime.decoderune
      10ms  1.85% 98.15%       10ms  1.85%  runtime.madvise
      10ms  1.85%   100%      390ms 72.22%  strings_test.TestCompareStrings
         0     0%   100%       10ms  1.85%  runtime.(*mcache).allocLarge
         0     0%   100%       10ms  1.85%  runtime.(*mheap).alloc
(pprof) disasm cmpbody
no matches found for regexp: cmpbody
(pprof) disasm unicode.to
no matches found for regexp: unicode.to
(pprof) disasm .*
no matches found for regexp: .*
(pprof) 

I have not checked whether this is Mac-specific.

[ALTree]

go test -cpuprofile=x.prof strings will leave a strings.test binary in the working directory. If pprof is invoked as go tool pprof x.prof, disasm fails because it's looking for the binary in /tmp/, and it's not there:

(pprof) disasm cmpbody
open /tmp/go-build477592094/b001/strings.test: no such file or directory
no matches found for regexp: cmpbody

but if the binary (which is in wd) is explicitly passed as go tool pprof strings.test x.prof, then disasm works correctly.

FWIW, I see the same behaviour with go1.17.5 (above tests are from tip).

(This is on Linux).

[ianlancetaylor]

Agreed, as far as I can tell this has never worked.

This works (on linux-amd64):

go test -c strings
./strings.test -test.cpuprofile=x.prof
go tool pprof x.prof
disasm cmpbody

Removing the release-blocker label.

[cespare]

I stub my toe on this UX about every other time I use pprof.

[cherrymui]

It seems the go command first runs the binary in the tmp directory, collects the profile, then moves it to the current directory. The file path recorded is the one in the tmp directory.

$WORK/b001/strings.test -test.paniconexit0 -test.timeout=10m0s -test.outputdir=/tmp -test.cpuprofile=x.prof
mkdir -p /tmp/
mv $WORK/b001/strings.test /tmp/strings.test

Perhaps the go command can move the file first then run it?

Another part is that it seems the file names recorded in the profile are from profile.Mapping, which is from reading /proc/self/maps, which probably works only on Linux. So on macOS we may need to always pass the executable file name to pprof, even if the go command does the mv first.

[rsc]

Thanks. Indeed, not a release blocker. It should be easy to run the final executable instead of the one from /tmp to fix Linux. For the Mac we should be able to record os.Executable, which might be sufficient. All good things for a future release.

[fumin]

Getting the same problem on Windows:

PS C:\Users\a3367\work\misc\seg> go run .\cmd\vizccl\main.go
2022/03/29 13:28:17.416938 C:/Users/a3367/work/misc/seg/cmd/vizccl/main.go:45: png write start output\vizqqq.png
2022/03/29 13:28:48.685875 C:/Users/a3367/work/misc/seg/cmd/vizccl/main.go:55: png write end output\vizqqq.png
PS C:\Users\a3367\work\misc\seg>
PS C:\Users\a3367\work\misc\seg\output> go tool pprof .\png_encode.pprof
Type: cpu
Time: Mar 29, 2022 at 1:28pm (CST)
Duration: 31.43s, Total samples = 17.53s (55.77%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 16.92s, 96.52% of 17.53s total
Dropped 91 nodes (cum <= 0.09s)
Showing top 10 nodes out of 29
      flat  flat%   sum%        cum   cum%
     7.96s 45.41% 45.41%     13.07s 74.56%  image/png.filter
        2s 11.41% 56.82%      2.01s 11.47%  image/png.abs
     1.74s  9.93% 66.74%      1.74s  9.93%  runtime.memmove
     1.56s  8.90% 75.64%      1.56s  8.90%  image/png.abs8
     1.44s  8.21% 83.86%      3.46s 19.74%  image/png.paeth
     0.90s  5.13% 88.99%      0.90s  5.13%  hash/adler32.update
     0.80s  4.56% 93.55%      0.81s  4.62%  compress/flate.(*deflateFast).matchLen
     0.29s  1.65% 95.21%      0.31s  1.77%  compress/flate.(*huffmanEncoder).bitCounts
     0.12s  0.68% 95.89%      0.12s  0.68%  runtime.asyncPreempt
     0.11s  0.63% 96.52%      1.04s  5.93%  compress/flate.(*deflateFast).encode
(pprof) disasm png.abs8
Total: 17.53s
(pprof)

$ go version
go version go1.17.6 windows/amd64

go env Output

$ go env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=C:\Users\a3367\AppData\Local\go-build
set GOENV=C:\Users\a3367\AppData\Roaming\go\env
set GOEXE=.exe
set GOEXPERIMENT=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\a3367\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=C:\Users\a3367\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.17.6
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=NUL
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\a3367\AppData\Local\Temp\go-build2334633044=/tmp/go-build -gno-record-gcc-switches
gdb --version: GNU gdb (GDB) 8.1