cmd/pprof: list output incorrect #30435
Description
What version of Go are you using (go version)?
go version go1.12 darwin/amd64
Does this issue reproduce with the latest release?
Yes
What operating system and processor architecture are you using (go env)?\
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/bill/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/bill/code/go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/p6/l5y36lvx3zvdc3gtfh0g_43w0000gn/T/go-build432551449=/tmp/go-build -gno-record-gcc-switches -fno-common"
</pre></details>
What did you do?
Using this code and uncommenting lines 41 and 42 to run a CPU profile.
https://github.com/ardanlabs/gotraining/tree/master/topics/go/profiling/trace
$ go build
$ ./trace > p.out
$ go tool pprof p.out
What did you expect to see?
On version 1.11.5 this is the output which is consistent with previous versions as well
(pprof) list main.find
Total: 810ms
ROUTINE ======================== main.find in /Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/go/profiling/trace/trace.go
0 760ms (flat, cum) 93.83% of Total
. . 65:func find(topic string, docs []string) int {
. . 66: var found int
. . 67:
. . 68: for _, doc := range docs {
. . 69: file := fmt.Sprintf("%s.xml", doc[:8])
. 650ms 70: f, err := os.OpenFile(file, os.O_RDONLY, 0)
. . 71: if err != nil {
. . 72: log.Printf("Opening Document [%s] : ERROR : %v", doc, err)
. . 73: return 0
. . 74: }
. . 75:
. 30ms 76: data, err := ioutil.ReadAll(f)
. . 77: if err != nil {
. . 78: f.Close()
. . 79: log.Printf("Reading Document [%s] : ERROR : %v", doc, err)
. . 80: return 0
. . 81: }
. . 82: f.Close()
. . 83:
. . 84: var d document
. 80ms 85: if err := xml.Unmarshal(data, &d); err != nil {
. . 86: log.Printf("Decoding Document [%s] : ERROR : %v", doc, err)
. . 87: return 0
. . 88: }
. . 89:
. . 90: for _, item := range d.Channel.Items {
(pprof)
What did you see instead?
Now on version 1.12 the output is wrong. The bulk of the syscall time for the Open call is missing from the output. The Total time is correct but the list and web commands are missing a bulk of the time for the system call.
(pprof) list main.find
Total: 820ms
ROUTINE ======================== main.find in /Users/bill/code/go/src/github.com/ardanlabs/gotraining/topics/go/profiling/trace/trace.go
0 80ms (flat, cum) 9.76% of Total
. . 65:func find(topic string, docs []string) int {
. . 66: var found int
. . 67:
. . 68: for _, doc := range docs {
. . 69: file := fmt.Sprintf("%s.xml", doc[:8])
. 30ms 70: f, err := os.OpenFile(file, os.O_RDONLY, 0)
. . 71: if err != nil {
. . 72: log.Printf("Opening Document [%s] : ERROR : %v", doc, err)
. . 73: return 0
. . 74: }
. . 75:
. . 76: data, err := ioutil.ReadAll(f)
. . 77: if err != nil {
. . 78: f.Close()
. . 79: log.Printf("Reading Document [%s] : ERROR : %v", doc, err)
. . 80: return 0
. . 81: }
. 10ms 82: f.Close()
. . 83:
. . 84: var d document
. 40ms 85: if err := xml.Unmarshal(data, &d); err != nil {
. . 86: log.Printf("Decoding Document [%s] : ERROR : %v", doc, err)
. . 87: return 0
. . 88: }
. . 89:
. . 90: for _, item := range d.Channel.Items {
(pprof)
With a little more inspection of the call graph, the builk of the time moved here.
(pprof) list runtime.mstart
Total: 820ms
ROUTINE ======================== runtime.mstart in /usr/local/go/src/runtime/proc.go
0 580ms (flat, cum) 70.73% of Total
. . 1148:// May run during STW (because it doesn't have a P yet), so write
. . 1149:// barriers are not allowed.
. . 1150://
. . 1151://go:nosplit
. . 1152://go:nowritebarrierrec
. 580ms 1153:func mstart() {
. . 1154: _g_ := getg()
. . 1155:
. . 1156: osStack := _g_.stack.lo == 0
. . 1157: if osStack {
. . 1158: // Initialize stack bounds from system stack.