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

[segevfiner]

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)
	}
}

2. 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]

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

[segevfiner]

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]

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