pprof source and disasm views overcount recursive functions
- 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:

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
Assessment
This issue has not been assessed yet.