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.

Sign up for GitHub

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

runtime/pprof: go test -cpuprofile outputs no samples in MacOS #28682

Closed
segevfiner opened this issue Nov 8, 2018 · 3 comments
Closed

runtime/pprof: go test -cpuprofile outputs no samples in MacOS #28682

segevfiner opened this issue Nov 8, 2018 · 3 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@segevfiner
Copy link
Contributor

What did you do?

  1. Run go test -cpuprofile cpu.prof on a package containing only this file:
// foo_test.go
package foo

import (
	"testing"
	"time"
)

func TestFoo(t *testing.T) {
	x := 1
	for i := 0; i < 100; i++ {
		x *= 2
		time.Sleep(100 * time.Millisecond)
	}
}
  1. Run go tool pprof cpu.prof, you get:
Type: cpu
Time: Nov 8, 2018 at 11:44pm (IST)
Duration: 10.26s, Total samples = 0
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%
(pprof)

What did you expect to see?

CPU profiling results.

What did you see instead?

0 samples, no results.

Does this issue reproduce with the latest release (go1.11.2)?

Yes.

System details

go version go1.10.4 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/<snip>/Library/Caches/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/<snip>/go"
GORACE=""
GOROOT="/usr/local/Cellar/go@1.10/1.10.4/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go@1.10/1.10.4/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
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/b_/c6yh0ksn63d1yy192x2p9f4c0000gn/T/go-build863644672=/tmp/go-build -gno-record-gcc-switches -fno-common"
GOROOT/bin/go version: go version go1.10.4 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.10.4
uname -v: Darwin Kernel Version 17.7.0: Wed Oct 10 23:06:14 PDT 2018; root:xnu-4570.71.13~1/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.13.6
BuildVersion:	17G3025
lldb --version: lldb-1000.0.38.2
  Swift-4.2
@ALTree
Copy link
Member

ALTree commented Nov 8, 2018

Why does it surprise you that -cpuprofile collects no samples? That program does basically nothing:

Performance counter stats for './test':

    12.557030      task-clock (msec)         #    0.001 CPUs utilized          
     
    10.019654716 seconds time elapsed
     0.000000000 seconds user
     0.020159000 seconds sys

@ALTree ALTree added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Nov 8, 2018
@ALTree ALTree changed the title go test -cpuprofile outputs no samples in MacOS runtime/pprof: go test -cpuprofile outputs no samples in MacOS Nov 8, 2018
@segevfiner
Copy link
Contributor Author

I tried to profile a program which mostly blocks on network IO, which is why I submitted sample code which mostly uses sleep.

I think I misunderstood and assumed that the CPU profiler acts like other profilers I have used which show you where you code is spending time. But if the CPU profiler is ignoring sleeping goroutines completely, only sampling active CPU time, than I guess I need to use a different tool to find where such code blocks...

@ALTree
Copy link
Member

ALTree commented Nov 8, 2018

You may want to have a look at the block profile

$ go test -blockprofile=block.prof foo_test.go

$ go tool pprof block.prof 
File: foo.test
Type: delay

(pprof) top10
Showing nodes accounting for 10.01s, 100% of 10.01s total
Dropped 2 nodes (cum <= 0.05s)
      flat  flat%   sum%        cum   cum%
    10.01s   100%   100%     10.01s   100%  runtime.chanrecv1
         0     0%   100%     10.01s   100%  main.main
         0     0%   100%     10.01s   100%  runtime.main
         0     0%   100%     10.01s   100%  testing.(*M).Run
         0     0%   100%     10.01s   100%  testing.(*T).Run
         0     0%   100%     10.01s   100%  testing.runTests
         0     0%   100%     10.01s   100%  testing.runTests.func1
         0     0%   100%     10.01s   100%  testing.tRunner

@golang golang locked and limited conversation to collaborators Nov 8, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ALTree @gopherbot @segevfiner