pprof where is my time going

[ajay aggarwal]

Hello,

I am trying to analyze why I am getting low throughput for my app. Below is the 30 second CPU profile output. I would expect more time spent in net/http serve. Not sure if runtime.mcall and runtime.schedule taking almost 1/4th of the time is concerning. When I did a "web mcall" it didn't show who is calling mcall. The web graph started with mcall. Any help will be much appreciated. Thanks!

(pprof) top 5 -cum

0.09s of 32s total ( 0.28%)

Dropped 449 nodes (cum <= 0.16s)

Showing top 5 nodes out of 249 (cum >= 7.49s)

     flat  flat%   sum%        cum   cum%

        0     0%     0%     22.17s 69.28%  runtime.goexit

    0.01s 0.031% 0.031%      8.73s 27.28%  net/http.(*conn).serve

        0     0% 0.031%      7.77s 24.28%  runtime.mcall

    0.07s  0.22%  0.25%      7.62s 23.81%  runtime.schedule

    0.01s 0.031%  0.28%      7.49s 23.41%  net/http.serverHandler.ServeHTTP

[Ian Lance Taylor]

This is misleading. runtime.mcall and runtime.schedule tend to appear
in many backtraces because of how the scheduler works, and that causes
them to appear high up in the cumulative profile. It doesn't mean
anything, it just means that the goroutine scheduler makes much of the
work appear to be called from mcall and schedule. In a cumulative
profile you need to look farther down into your program's code to see
where the work is happening.

Ian

[ajay aggarwal]

Thanks for the explanation on runtime.mcall and runtime.schedule. Is it true that if your application gets blocked a lot (say on I/O) then CPU profile will not help you to figure out where you are getting blocked the most? The blocked goroutines will not show up in the CPU profile samples..

[Ian Lance Taylor]

On Mon, Jul 18, 2016 at 10:28 AM, ajay aggarwal <ajay...@gmail.com> wrote:
> Thanks for the explanation on runtime.mcall and runtime.schedule. Is it true
> that if your application gets blocked a lot (say on I/O) then CPU profile
> will not help you to figure out where you are getting blocked the most? The
> blocked goroutines will not show up in the CPU profile samples..

That is correct. The CPU profile will show you where the program is
using the most CPU time. It won't show you where the program is
waiting for something to happen.

The execution tracer may help; see https://golang.org/s/go15trace .

Ian

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

[ajay aggarwal]

Thanks Ian. But Its not clear how to get execution trace from that document (https://golang.org/s/go15trace). When I list profiles for my application, I get following list

block,goroutine,heap,threadcreate

And when I try to curl to http://my-app/debug/pprof/trace?seconds=30" for my application, I get the error that no such profile. 

How do I enable execution tracer profile for my app?

Thanks!

Ajay

[ajay aggarwal]

Apparently its very easy to collect execution tracer profile

runtime.trace.Start (io.Writer)

time.Sleep(N seconds)

runtime.trace.Stop()

And to analyze/look at the collected profile

go tool trace /path/to/your/app/executable <binary-trace-file-collected-above>