Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

cmd/pprof: list output incorrect #30435

Closed
ardan-bkennedy opened this issue Feb 27, 2019 · 3 comments
Closed

cmd/pprof: list output incorrect #30435

ardan-bkennedy opened this issue Feb 27, 2019 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@ardan-bkennedy
Copy link

ardan-bkennedy commented Feb 27, 2019 •
edited

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.
@bcmills
Copy link
Contributor

bcmills commented Feb 27, 2019

CC @hyangah

@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 27, 2019
@bcmills bcmills added this to the Go1.13 milestone Feb 27, 2019
@andybons andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
@ardan-bkennedy
Copy link
Author

This appears to have been fixed on tip. I was looking at this last week. Someone might want to double check it.

@ardan-bkennedy
Copy link
Author

Not an issue any longer

@golang golang locked and limited conversation to collaborators Jun 12, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
5 participants
@rsc @andybons @ardan-bkennedy @bcmills @gopherbot