runtime/pprof: no samples in profile output

[eapache]

Running on Ubuntu 15.10 x64, on an Intel Haswell i7-4790. I have seen identical behaviour with go 1.5.1 as provided by Ubuntu's repositories and go 1.5.3 as downloaded from https://golang.org/.

I was trying to profile one of my programs, but I was getting weirdly empty profiles (not empty 0-byte files, but syntactically complete pprof files containing no useful samples). I googled around a bunch and eliminated a bunch of common causes before reporting:

The sample app I am profiling is https://gist.github.com/eapache/580b7dbd8800fe9a3234. It runs for ~40 seconds on my machine with no sleeps and only minimal printing to standard output, which should be more than enough to generate samples. I know that the CPU-bound string building dummy code is being run and not optimized out, because I can see it getting slower as the string size grows.

It is running to completion and StopCPUProfile() is getting called. If I interrupt it or remove that, I get a 0-byte profile file instead, which makes sense.

I am not running on OSX or any platform which is known to have profiling problems as far as I have been able to determine.

When inspecting the profile file with pprof I get no errors, but useless output like the following:

(pprof) top10
39.78s of 39.78s total (  100%)
      flat  flat%   sum%        cum   cum%
    39.78s   100%   100%     39.78s   100%  

My first instinct was that I was running without debug symbols for some reason, but I still get correct backtraces if I put a panic in somewhere. I'm really not sure what's going on here. I'm happy to try patches, upload the profile file, or whatever else you might need to debug this.

[bradfitz]

Does closing f help? And always check for return values from *os.File.Close when the file is opened for write.

[eapache]

I have updated the gist to close f (with error-check) after stopping the profile. No effect.

[bradfitz]

Can you also try Go 1.6? Go 1.5 will no longer be maintained in a few days.

[eapache]

Identical behaviour with 1.6rc2, although the dummy code ran about 20% faster :)

[cespare]

@eapache what is your invocation for building and running your test program and running pprof?

How big is the generated profile.out?

I don't see this problem on OS X (El Capitan) or Ubuntu 14.04. I get something like

(pprof) top10
40.69s of 65.24s total (62.37%)
Dropped 147 nodes (cum <= 0.33s)
Showing top 10 nodes out of 112 (cum >= 1.06s)
      flat  flat%   sum%        cum   cum%
    11.66s 17.87% 17.87%     11.66s 17.87%  runtime.futex
     7.85s 12.03% 29.90%      7.85s 12.03%  runtime.memclr
     6.05s  9.27% 39.18%      6.38s  9.78%  runtime.scanblock
     5.64s  8.65% 47.82%      5.64s  8.65%  runtime.memmove
     2.91s  4.46% 52.28%      2.91s  4.46%  runtime.xchg
     1.87s  2.87% 55.15%      2.39s  3.66%  runtime.scanobject
     1.32s  2.02% 57.17%     11.19s 17.15%  runtime.findrunnable
     1.24s  1.90% 59.07%      1.24s  1.90%  runtime.usleep
     1.09s  1.67% 60.74%     16.86s 25.84%  runtime.mallocgc
     1.06s  1.62% 62.37%      1.06s  1.62%  runtime.cas

[davecheney]

What is the command line you are using to invoke pprof? You should be using

 go tool pprof $binary $profile

The example you posted is consistent with the common error of omitting
$binary

On Mon, 15 Feb 2016, 06:57 Caleb Spare notifications@github.com wrote:

@eapache https://github.com/eapache what is your invocation for
building and running your test program and running pprof?

How big is the generated profile.out?

I don't see this problem on OS X (El Capitan) or Ubuntu 14.04. I get
something like

(pprof) top10
40.69s of 65.24s total (62.37%)
Dropped 147 nodes (cum <= 0.33s)
Showing top 10 nodes out of 112 (cum >= 1.06s)
flat flat% sum% cum cum%
11.66s 17.87% 17.87% 11.66s 17.87% runtime.futex
7.85s 12.03% 29.90% 7.85s 12.03% runtime.memclr
6.05s 9.27% 39.18% 6.38s 9.78% runtime.scanblock
5.64s 8.65% 47.82% 5.64s 8.65% runtime.memmove
2.91s 4.46% 52.28% 2.91s 4.46% runtime.xchg
1.87s 2.87% 55.15% 2.39s 3.66% runtime.scanobject
1.32s 2.02% 57.17% 11.19s 17.15% runtime.findrunnable
1.24s 1.90% 59.07% 1.24s 1.90% runtime.usleep
1.09s 1.67% 60.74% 16.86s 25.84% runtime.mallocgc
1.06s 1.62% 62.37% 1.06s 1.62% runtime.cas

—
Reply to this email directly or view it on GitHub
#14324 (comment).

[cespare]

@davecheney good call. #10863 is the relevant issue.

[minux]

Merged into #10863.

[eapache]

Yes, that was the issue, sorry for the noise. Next time I'll actually try reading the docs :(