pprof cpu profiler taking very few samples

[Charlie Andrews]

I am trying to profile a server. My code to start and stop the profiler is as follows:

        if *profile != "" {
                f, err := os.Create(*profile)
                if err != nil {
                        log.Fatal(err)
                }
                pprof.StartCPUProfile(f)
                sigChan := make(chan os.Signal)
                signal.Notify(sigChan, syscall.SIGINT)
                go func() {
                        s := <-sigChan
                        log.Printf("Recieved: %+v\n", s)
                        pprof.StopCPUProfile()
                        os.Exit(0)
                }()
        }

I start the server with the profile flag and then start a stress testing script. The script finishes and I send it a SIGINT. When I run 'go tool pprof <binName> <profileName>' I get the pprof prompt. I run the 'top10' command, it prints the top 10, but I only have 41 samples. My understanding is the that profiler takes about 100 samples / 1 second. the process is running for at least a minute, so I should be getting well over 6000 samples, but I only get around 40 every time I run it. Why would this be happening? The output of the top10 command is:

(pprof) top10
Total: 41 samples
       3   7.3%   7.3%        3   7.3% runtime.MSpan_Sweep
       2   4.9%  12.2%        6  14.6% encoding/gob.(*Decoder).decodeInterface
       2   4.9%  17.1%       15  36.6% encoding/json.(*mapEncoder).encode
       2   4.9%  22.0%        2   4.9% reflect.packEface
       2   4.9%  26.8%        2   4.9% runtime.usleep
       2   4.9%  31.7%        2   4.9% runtime.xchg
       2   4.9%  36.6%        3   7.3% settype
       1   2.4%  39.0%        1   2.4% ExternalCode
       1   2.4%  41.5%        3   7.3% bytes.(*Buffer).grow
       1   2.4%  43.9%        1   2.4% encoding/json.stringValues.Less

[Andy Bonventre]

Which OS are you running on? If on Mac – http://research.swtch.com/macpprof

Otherwise, it’s still valuable to get an idea of your environment.

A

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Charlie Andrews]

On Tue, May 20, 2014 at 03:54:06PM -0400, Andy Bonventre wrote:
> Which OS are you running on? If on Mac – http://research.swtch.com/macpprof
>
> Otherwise, it’s still valuable to get an idea of your environment.
>
> A

I am running this on ArchLinux x86_64.

I have now tried something a bit different, by specifying the profile
that I want to record: "goroutine". This is how I'm doing it now:

prof := pprof.Lookup("goroutine")
err = prof.WriteTo(f, 1)

And it's creating the profile in the file just fine, but I get the
error, "file.prof: header size >= 2**16". So I'm looking into that now.

-Charlie

[Dave Cheney]

I wrote this a while back, maybe it is useful for you.

https://github.com/davecheney/profile

[Charlie Andrews]

On Wed, May 21, 2014 at 02:00:26AM -0700, Dave Cheney wrote:
> I wrote this a while back, maybe it is useful for you.
>
> https://github.com/davecheney/profile

Dave,

Cool project. I used your project instead of the stdlib one and still
only got 32 samples. I feel that I am not using this tool correctly.
Would the profiling tool be able to pick up what's happening down the
rabbit hole of a go routine upon handling a request? I'm a little
confused as to why I'm only getting a few samples on a process that runs
for a while (~2min). Any suggestions on what I should try?

-Charlie

[distributed]

This might be a stupid question. You say your process runs for at least a minute. Does your process actually use that much CPU time?

In other words, what is the output of time ./yourprogram ?

[Charlie Andrews]

On Wed, May 21, 2014 at 06:54:20AM -0700, distributed wrote:
> This might be a stupid question. You say your process runs for at least a
> minute. Does your process actually use that much CPU time?
>
> In other words, what is the output of time ./yourprogram ?

It's a webserver, so it doesn't really have output besides logs, but I
am throwing a few thousand requests at it, so I would assume that there
would be enough CPU time to grab a few thousand samples, but I only get
in the low double digits. For now I'm using perf top, which is somewhat
helpful, but I thought that pprof would be better since it is
go-specific.

-Charlie

[distributed]

Sorry, I missed out on the SIGINT part.

What does ps -ef say?

[Charlie Andrews]

On Wed, May 21, 2014 at 07:36:31AM -0700, distributed wrote:
> Sorry, I missed out on the SIGINT part.
>
> What does ps -ef say?

$ ps -ef | grep server
charlie 1883 1007 0 09:06 pts/4 00:00:02 ./server

-Charlie

[distributed]

$ ps -ef | grep server
charlie   1883  1007  0 09:06 pts/4    00:00:02 ./server 

This means that over its whole lifetime, the process in questio has only used 2 seconds of CPU time. If you had the profiler running for the whole lifetime of this process, I would expect the profile to contain about 200 samples.

I think your program is just not taking a lot of CPU time, therefore there is not much to profile.

 

[Vedran Vekic]

I had exactly the same problem (also using Arch linux, hmmm..).

I used runtime.SetCPUProfileRate() before starting the profiler with pprof.StartCPUProfile(), and I managed to get a decent number of samples.

[Charlie Andrews]

On Wed, May 21, 2014 at 07:51:27AM -0700, distributed wrote:
>
> I think your program is just not taking a lot of CPU time, therefore there
> is not much to profile.

Ahh... That helps a lot since I know not to look at that server but
another. The other server had over 8000 samples in it. Thanks for your
help!

-Charlie