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

runtime/pprof: no samples in profile output #14324

Closed
eapache opened this issue Feb 14, 2016 · 9 comments
Closed

runtime/pprof: no samples in profile output #14324

eapache opened this issue Feb 14, 2016 · 9 comments
Labels
FrozenDueToAge

Comments

@eapache
Copy link

eapache commented Feb 14, 2016

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
Copy link
Contributor

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

@eapache
Copy link
Author

eapache commented Feb 14, 2016

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

@bradfitz
Copy link
Contributor

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

@eapache
Copy link
Author

eapache commented Feb 14, 2016

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

@cespare
Copy link
Contributor

cespare commented Feb 14, 2016

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

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 cespare mentioned this issue Feb 14, 2016
Closed
@cespare
Copy link
Contributor

cespare commented Feb 14, 2016

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

@minux
Copy link
Member

minux commented Feb 15, 2016

Merged into #10863.

@minux minux closed this as completed Feb 15, 2016
@eapache
Copy link
Author

eapache commented Feb 15, 2016

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

@golang golang locked and limited conversation to collaborators Feb 28, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@bradfitz @davecheney @minux @cespare @eapache @gopherbot