cmd/pprof: list command cannot find stdlib sources

(pprof) list huffSym
Total: 5.30s
ROUTINE ======================== compress/flate.(*decompressor).huffSym in /usr/local/go/src/compress/flate/inflate.go
     980ms      1.53s (flat, cum) 28.87% of Total
 Error: open /usr/local/go/src/compress/flate/inflate.go: no such file or directory
(pprof)

 $ which go
/home/opennota/go151/bin/go

I never had Go in /usr/local/go, I just unpacked the official tarball into my home directory (Linux x86_64) and set PATH accordingly; pprof tool seems to disregard that.

[bradfitz]

The default GOROOT baked into the binaries is /usr/local/go.

See the docs: https://golang.org/doc/install#tarball_non_standard

No difference with the set and exported GOROOT. go tool pprof still complains:

$ go tool pprof main main.mprof
Entering interactive mode (type "help" for commands)
(pprof) list
Total: 3.79MB
ROUTINE ======================== bufio.(*Reader).ReadByte in /usr/local/go/src/bufio/bufio.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/bufio/bufio.go: no such file or directory
ROUTINE ======================== bufio.(*Reader).fill in /usr/local/go/src/bufio/bufio.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/bufio/bufio.go: no such file or directory
ROUTINE ======================== bytes.(*Buffer).WriteByte in /usr/local/go/src/bytes/buffer.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/bytes/buffer.go: no such file or directory
ROUTINE ======================== bytes.(*Buffer).grow in /usr/local/go/src/bytes/buffer.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/bytes/buffer.go: no such file or directory
ROUTINE ======================== bytes.makeSlice in /usr/local/go/src/bytes/buffer.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/bytes/buffer.go: no such file or directory

I think this doesn't work as expected.

[bradfitz]

Rebuild your main binary?

@bradfitz
Did it already when profiling after your response (go build && ./main); even tried to remove old profile. Rebuilt and profiled it again just now and still having the issue.

$ echo $GOROOT
/home/opennota/go151

$ ls $GOROOT
api      bin   CONTRIBUTING.md  doc          lib      misc     pkg        robots.txt  test
AUTHORS  blog  CONTRIBUTORS     favicon.ico  LICENSE  PATENTS  README.md  src         VERSION

Removed $GOPATH/pkg/ and reinstalled (go install) my package. Still having the issue.

[bradfitz]

I'll reopen this bug, but I have no advice. I've never seen this problem myself, and I use pprof regularly, with my GOROOT under my $HOME, not in /usr/local/go.

Repeated all the steps from the very beginning. Here's the full log.

opennota@localhost ~ $ mkdir golang-temp
opennota@localhost ~ $ cd golang-temp
opennota@localhost ~/golang-temp $ mkdir gocode
opennota@localhost ~/golang-temp $ tar xf ~/go1.5.1.linux-amd64.tar.gz 
opennota@localhost ~/golang-temp $ ls
go  gocode
opennota@localhost ~/golang-temp $ export GOROOT=`realpath go`
opennota@localhost ~/golang-temp $ ls $GOROOT
api      bin   CONTRIBUTING.md  doc          lib      misc     pkg        robots.txt  test
AUTHORS  blog  CONTRIBUTORS     favicon.ico  LICENSE  PATENTS  README.md  src         VERSION
opennota@localhost ~/golang-temp $ export PATH=`realpath go/bin`:/usr/bin:/bin
opennota@localhost ~/golang-temp $ which go
/home/opennota/golang-temp/go/bin/go
opennota@localhost ~/golang-temp $ export GOPATH=`realpath gocode`
opennota@localhost ~/golang-temp $ cd gocode/
opennota@localhost ~/golang-temp/gocode $ gvim test.go
opennota@localhost ~/golang-temp/gocode $ go test 
# _/home/opennota/golang-temp/gocode
./test.go:13: undefined: buf
./test.go:17: not enough arguments in call to flate.NewWriter
./test.go:17: multiple-value flate.NewWriter() in single-value context
./test.go:20: undefined: log in log.Fatal
./test.go:24: undefined: log in log.Fatal
./test.go:29: undefined: log in log.Fatal
opennota@localhost ~/golang-temp/gocode $ go test 
?       _/home/opennota/golang-temp/gocode   [no test files]
opennota@localhost ~/golang-temp/gocode $ go build
opennota@localhost ~/golang-temp/gocode $ cat test.go 
package main

import (
        "bytes"
        "compress/flate"
        "log"
        "math/rand"
        "os"
        "runtime/pprof"
)

func main() {
        data := make([]byte, 100000000)
        for i := 0; i < len(data); i++ {
                data[i] = byte(rand.Intn(256))
        }
        var buf bytes.Buffer
        w, _ := flate.NewWriter(&buf, 9)
        _, err := w.Write(data)
        if err != nil {
                log.Fatal(err)
        }
        err = w.Close()
        if err != nil {
                log.Fatal(err)
        }

        f, err := os.Create("a.prof")
        if err != nil {
                log.Fatal(err)
        }
        pprof.WriteHeapProfile(f)
        f.Close()
}
opennota@localhost ~/golang-temp/gocode $ go build
opennota@localhost ~/golang-temp/gocode $ ls
gocode  test.go
opennota@localhost ~/golang-temp/gocode $ ./gocode 
opennota@localhost ~/golang-temp/gocode $ ls
a.prof  gocode  test.go
opennota@localhost ~/golang-temp/gocode $ which go
/home/opennota/golang-temp/go/bin/go
opennota@localhost ~/golang-temp/gocode $ echo $GOROOT
/home/opennota/golang-temp/go
opennota@localhost ~/golang-temp/gocode $ go tool pprof a.prof 
Entering interactive mode (type "help" for commands)
(pprof) top10 
4.57MB of 4.57MB total (  100%)
      flat  flat%   sum%        cum   cum%
    4.57MB   100%   100%     4.57MB   100%  
(pprof) list
Total: 4.57MB
(pprof) opennota@localhost ~/golang-temp/gocode $ go build
opennota@localhost ~/golang-temp/gocode $ rm a.prof 
opennota@localhost ~/golang-temp/gocode $ ./gocode 
opennota@localhost ~/golang-temp/gocode $ go tool pprof gocode a.prof 
Entering interactive mode (type "help" for commands)
(pprof) top10
128.66MB of 129.16MB total (99.61%)
Dropped 10 nodes (cum <= 0.65MB)
Showing top 10 nodes out of 14 (cum >= 32.12MB)
      flat  flat%   sum%        cum   cum%
   95.38MB 73.84% 73.84%   128.66MB 99.61%  main.main
   32.12MB 24.87% 98.72%    32.12MB 24.87%  bytes.makeSlice
    1.16MB   0.9% 99.61%     1.16MB   0.9%  compress/flate.(*compressor).init
         0     0% 99.61%    32.12MB 24.87%  bytes.(*Buffer).Write
         0     0% 99.61%    32.12MB 24.87%  bytes.(*Buffer).grow
         0     0% 99.61%    32.12MB 24.87%  compress/flate.(*Writer).Write
         0     0% 99.61%    32.12MB 24.87%  compress/flate.(*compressor).deflate
         0     0% 99.61%    32.12MB 24.87%  compress/flate.(*compressor).write
         0     0% 99.61%    32.12MB 24.87%  compress/flate.(*compressor).writeBlock
         0     0% 99.61%    32.12MB 24.87%  compress/flate.(*huffmanBitWriter).writeBlock
(pprof) list
Total: 129.16MB
ROUTINE ======================== bytes.(*Buffer).Write in /usr/local/go/src/bytes/buffer.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/bytes/buffer.go: no such file or directory
ROUTINE ======================== bytes.(*Buffer).grow in /usr/local/go/src/bytes/buffer.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/bytes/buffer.go: no such file or directory
ROUTINE ======================== bytes.makeSlice in /usr/local/go/src/bytes/buffer.go
   32.12MB    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/bytes/buffer.go: no such file or directory
ROUTINE ======================== compress/flate.(*Writer).Write in /usr/local/go/src/compress/flate/deflate.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/compress/flate/deflate.go: no such file or directory
ROUTINE ======================== compress/flate.(*compressor).deflate in /usr/local/go/src/compress/flate/deflate.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/compress/flate/deflate.go: no such file or directory
ROUTINE ======================== compress/flate.(*compressor).init in /usr/local/go/src/compress/flate/deflate.go
    1.16MB     1.16MB (flat, cum)   0.9% of Total
 Error: open /usr/local/go/src/compress/flate/deflate.go: no such file or directory
ROUTINE ======================== compress/flate.(*compressor).write in /usr/local/go/src/compress/flate/deflate.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/compress/flate/deflate.go: no such file or directory
ROUTINE ======================== compress/flate.(*compressor).writeBlock in /usr/local/go/src/compress/flate/deflate.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/compress/flate/deflate.go: no such file or directory
ROUTINE ======================== compress/flate.(*huffmanBitWriter).writeBlock in /usr/local/go/src/compress/flate/huffman_bit_writer.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_bit_writer.go: no such file or directory
ROUTINE ======================== compress/flate.(*huffmanBitWriter).writeBytes in /usr/local/go/src/compress/flate/huffman_bit_writer.go
         0    32.12MB (flat, cum) 24.87% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_bit_writer.go: no such file or directory
ROUTINE ======================== compress/flate.(*huffmanEncoder).assignEncodingAndSize in /usr/local/go/src/compress/flate/huffman_code.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_code.go: no such file or directory
ROUTINE ======================== compress/flate.(*huffmanEncoder).bitCounts in /usr/local/go/src/compress/flate/huffman_code.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_code.go: no such file or directory
ROUTINE ======================== compress/flate.(*huffmanEncoder).generate in /usr/local/go/src/compress/flate/huffman_code.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_code.go: no such file or directory
ROUTINE ======================== compress/flate.NewWriter in /usr/local/go/src/compress/flate/deflate.go
         0     1.16MB (flat, cum)   0.9% of Total
 Error: open /usr/local/go/src/compress/flate/deflate.go: no such file or directory
ROUTINE ======================== compress/flate.sortByFreq in /usr/local/go/src/compress/flate/huffman_code.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_code.go: no such file or directory
ROUTINE ======================== compress/flate.sortByLiteral in /usr/local/go/src/compress/flate/huffman_code.go
         0          0 (flat, cum)     0% of Total
 Error: open /usr/local/go/src/compress/flate/huffman_code.go: no such file or directory
ROUTINE ======================== main.main in /home/opennota/golang-temp/gocode/test.go
   95.38MB   128.66MB (flat, cum) 99.61% of Total
         .          .      8:   "os"
         .          .      9:   "runtime/pprof"
         .          .     10:)
         .          .     11:
         .          .     12:func main() {
   95.38MB    95.38MB     13:   data := make([]byte, 100000000)
         .          .     14:   for i := 0; i < len(data); i++ {
         .          .     15:           data[i] = byte(rand.Intn(256))
         .          .     16:   }
         .          .     17:   var buf bytes.Buffer
         .     1.16MB     18:   w, _ := flate.NewWriter(&buf, 9)
         .    32.12MB     19:   _, err := w.Write(data)
         .          .     20:   if err != nil {
         .          .     21:           log.Fatal(err)
         .          .     22:   }
         .          .     23:   err = w.Close()
         .          .     24:   if err != nil {
ROUTINE ======================== runtime.goexit in /usr/local/go/src/runtime/asm_amd64.s
         0   128.66MB (flat, cum) 99.61% of Total
 Error: open /usr/local/go/src/runtime/asm_amd64.s: no such file or directory
ROUTINE ======================== runtime.main in /usr/local/go/src/runtime/proc.go
         0   128.66MB (flat, cum) 99.61% of Total
 Error: open /usr/local/go/src/runtime/proc.go: no such file or directory
ROUTINE ======================== runtime.malg in /usr/local/go/src/runtime/proc1.go
  512.19kB   512.19kB (flat, cum)  0.39% of Total
 Error: open /usr/local/go/src/runtime/proc1.go: no such file or directory
ROUTINE ======================== runtime.mcommoninit in /usr/local/go/src/runtime/proc1.go
         0   512.19kB (flat, cum)  0.39% of Total
 Error: open /usr/local/go/src/runtime/proc1.go: no such file or directory
ROUTINE ======================== runtime.mpreinit in /usr/local/go/src/runtime/os1_linux.go
         0   512.19kB (flat, cum)  0.39% of Total
 Error: open /usr/local/go/src/runtime/os1_linux.go: no such file or directory
ROUTINE ======================== runtime.rt0_go in /usr/local/go/src/runtime/asm_amd64.s
         0   512.19kB (flat, cum)  0.39% of Total
 Error: open /usr/local/go/src/runtime/asm_amd64.s: no such file or directory
ROUTINE ======================== runtime.schedinit in /usr/local/go/src/runtime/proc1.go
         0   512.19kB (flat, cum)  0.39% of Total
 Error: open /usr/local/go/src/runtime/proc1.go: no such file or directory
(pprof) opennota@localhost ~/golang-temp/gocode $ 
opennota@localhost ~/golang-temp/gocode $ ls $GOROOT
api      bin   CONTRIBUTING.md  doc          lib      misc     pkg        robots.txt  test
AUTHORS  blog  CONTRIBUTORS     favicon.ico  LICENSE  PATENTS  README.md  src         VERSION
opennota@localhost ~/golang-temp/gocode $ echo $GOROOT
/home/opennota/golang-temp/go

[ianlancetaylor]

The problem is that pprof won't attempt to translate from the compiled-in GOROOT to the working GOROOT. Thus compiling a binary for one GOROOT and then installing it in a different directory means that pprof can't find the standard package sources. Setting the GOROOT environment variable doesn't help, as pprof ignores it.

This is a real bug that is worth fixing.

[joegrasse]

Just curious if there is any workaround for this issue?

@joegrasse I suppose creating a symlink /usr/local/go -> /home/$USERNAME/go should solve the issue.

[joegrasse]

Yeah, If you don't have permission to do that though, I guess there isn't a workaround.

[dgryski]

Can you check if this happens with https://github.com/google/pprof ? If not, it will be closed by #16184