google / google/pprof

pprof source and disasm views overcount recursive functions

Open
#707 1 comment 0 reactions 0 assignees View on GitHub
Priority: p2 type: bug
Dominant language
Go
Stars
9.3k
Forks
671
Avg merge
1d 11h
Merged PRs (30d)
10

Description

### What version of pprof are you using?
`go tool pprof` with go1.18.3.

Full go env output

GO111MODULE=""

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/keyhan/.cache/go-build"
GOENV="/home/keyhan/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/keyhan/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/keyhan/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/snap/go/9848"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/snap/go/9848/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.18.3"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
GOWORK=""
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-build2938140119=/tmp/go-build -gno-record-gcc-switches"

### What operating system and processor architecture are you using?

Linux, x86-64 Intel.

### What did you do?

I opened the attached profile with `go tool pprof -http=: fac.pb.gz`,
and navigated to the "Sources" page. Here is the output:

![Screenshot 2022-06-26 at 13-03-34 e cpu](https://user-images.githubusercontent.com/22647613/175831921-c2df2c83-5486-495f-9bfc-5746594d1f06.png)

As you can see, it is claimed that `fac` took 6193% of the total time.
It is also said that it took 150 seconds, which is wrong since the
program took only a couple of seconds.

The issue also occurs with the command line version, although strangely
the output is better.

```
(pprof) list fac
Total: 2.43s
ROUTINE ======================== main.fac in /home/keyhan/exgo/e.go
2.43s 3.34s (flat, cum) 137.45% of Total
. . 2:
. . 3:import "os"
. . 4:import "log"
. . 5:import "runtime/pprof"
. . 6:
850ms 850ms 7:func fac(n uint64) uint64 {
60ms 60ms 8: if n == 0 {
. . 9: return 1
. . 10: } else {
1.52s 2.43s 11: return n * fac(n - 1)
. . 12: }
. . 13:}
. . 14:
. . 15:func main() {
. . 16: f, err := os.Create("example.pb.gz")
```

### What did you expect to see?

`cum%` should not be more than `100%`.

### What did you see instead?

`cum%` is claimed to be 6193%.

## Root cause(?)

I believe the root cause is this line of code:

https://github.com/google/pprof/blob/c488b8fa1db3fa467bf30beb5a1d6f4f10bb1b87/internal/report/source.go#L104

This is wrong, since the cumulative time spent in the current function
is not `fns.Sum()` if the function calls itself recursively. In those
cases some nodes will be counted multiple times.

## Source Code

```go
package main

import "os"
import "log"
import "runtime/pprof"

func fac(n uint64) uint64 {
if n == 0 {
return 1
} else {
return n * fac(n - 1)
}
}

func main() {
f, err := os.Create("example.pb.gz")
if err != nil {
log.Fatal("could not create CPU profile: ", err)
}
defer f.Close() // error handling omitted for example
if err := pprof.StartCPUProfile(f); err != nil {
log.Fatal("could not start CPU profile: ", err)
}
defer pprof.StopCPUProfile()
for i := 1; i <= 1e6; i++ {
fac(1000)
}
}
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.