pprof unrecognized profile format

[sporksmith]

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

$ go version
go version go1.17.1 linux/amd64

Does this issue reproduce with the latest release?

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/jnewsome/.cache/go-build"
GOENV="/home/jnewsome/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/jnewsome/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/jnewsome/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/jnewsome/opt/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/jnewsome/opt/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.1"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build3723000222=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I'm profiling the heap of shadow. Fully reproducing is a bit involved to get set up, but ultimately I'm running LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libtcmalloc_and_profiler.so.4 HEAPPROFILE=shadow.heap HEAP_PROFILE_TIME_INTERVAL=180 shadow ...

The earlier profiles are parsed correctly, but starting at 290 they are unparseable.

I'm then using pprof to analyze the heap dumps.

What did you expect to see?

Last working profile is shadow.heap.0289.heap.gz:

$ go tool pprof shadow.heap.0289.heap
File: shadow
Type: inuse_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

What did you see instead?

All the ones after that fail to parse, starting with
shadow.heap.0290.heap.gz

$ go tool pprof shadow.heap.0290.heap
tornet-0.001/shadow.heap.0290.heap: parsing profile: unrecognized profile format
failed to fetch any source profiles

[dr2chase]

@cherrymui

[cherrymui]

@sporksmith
Are the profiles truncated? Could they be read using https://github.com/google/pprof ? Thanks.

[sporksmith]

Are the profiles truncated?

I don't have any reason to think so. Here are some of the file sizes (289 and below seem to work, 290 and above don't):

$ ls -l tornet-0.001/shadow.heap.*
-rw-rw-r-- 1 jnewsome jnewsome    9564 Sep 22 22:42 tornet-0.001/shadow.heap.0001.heap
-rw-rw-r-- 1 jnewsome jnewsome  230601 Sep 22 22:42 tornet-0.001/shadow.heap.0002.heap
-rw-rw-r-- 1 jnewsome jnewsome  255956 Sep 22 22:42 tornet-0.001/shadow.heap.0003.heap
...
-rw-rw-r-- 1 jnewsome jnewsome 1020176 Sep 23 05:56 tornet-0.001/shadow.heap.0287.heap
-rw-rw-r-- 1 jnewsome jnewsome 1020176 Sep 23 05:57 tornet-0.001/shadow.heap.0288.heap
-rw-rw-r-- 1 jnewsome jnewsome 1020183 Sep 23 05:59 tornet-0.001/shadow.heap.0289.heap
-rw-rw-r-- 1 jnewsome jnewsome 1020184 Sep 23 06:00 tornet-0.001/shadow.heap.0290.heap
-rw-rw-r-- 1 jnewsome jnewsome 1020184 Sep 23 06:02 tornet-0.001/shadow.heap.0291.heap
-rw-rw-r-- 1 jnewsome jnewsome 1020184 Sep 23 06:03 tornet-0.001/shadow.heap.0292.heap
-rw-rw-r-- 1 jnewsome jnewsome 1020186 Sep 23 06:05 tornet-0.001/shadow.heap.0293.heap
...
-rw-rw-r-- 1 jnewsome jnewsome 1025441 Sep 23 07:38 tornet-0.001/shadow.heap.0355.heap
-rw-rw-r-- 1 jnewsome jnewsome 1025441 Sep 23 07:39 tornet-0.001/shadow.heap.0356.heap
-rw-rw-r-- 1 jnewsome jnewsome 1025444 Sep 23 07:41 tornet-0.001/shadow.heap.0357.heap
-rw-rw-r-- 1 jnewsome jnewsome 1025444 Sep 23 07:42 tornet-0.001/shadow.heap.0358.heap

I think the result is the same. IIUC after running $ go install github.com/google/pprof@latest, then running the $GOPATH/bin/pprof gives me that one, but go tool pprof gives me the "built in" one?

$ ~/go/bin/pprof tornet-0.001/shadow.heap.0290.heap
tornet-0.001/shadow.heap.0290.heap: parsing profile: unrecognized profile format
pprof: failed to fetch any source profiles

$ ~/go/bin/pprof tornet-0.001/shadow.heap.0289.heap
File: shadow
Type: inuse_space
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)

As you can tell from the timestamps, this is a pretty long-running tool, and there are a lot of allocations and deallocations. Maybe there's some int32 or smaller in the format that could be overflowing?

[sporksmith]

Oh; I didn't realize it's a text format. Indeed it looks like there's an int32 overflow:

diff tornet-0.001/shadow.heap.0289.heap tornet-0.001/shadow.heap.0290.heap
1,2c1,2
< heap profile: 2237252: 888238604 [2144665071: 188608279238] @ heapprofile
---
> heap profile: 2250136: 892383061 [-2147316050: 188867582594] @ heapprofile
...

[sporksmith]

Confirmed that after editing the file to change -2147316050 to 2147316050, pprof can parse it. Changing it to 21473160500 (something that won't fit in an int32) also works. I guess then this is a tcmalloc bug?

[cherrymui]

Thanks for looking into this. Yeah, it looks like a bug in tcmalloc (or whatever generates the profile). Closing as it is not a bug in Go.

IIUC after running $ go install github.com/google/pprof@latest, then running the $GOPATH/bin/pprof gives me that one, but go tool pprof gives me the "built in" one.

Yes. For the latter, go tool -n pprof will print the path of the binary.