code review 6443115: pprof: add contention profiling

pprof: add goroutine blocking profiling
The profiler collects goroutine blocking information similar to Google Perf Tools.
You may see an example of the profile (converted to svg) attached to
http://code.google.com/p/go/issues/detail?id=3946
The public API changes are:
+pkg runtime, func BlockProfile([]BlockProfileRecord) (int, bool)
+pkg runtime, func SetBlockProfileRate(int)
+pkg runtime, method (*BlockProfileRecord) Stack() []uintptr
+pkg runtime, type BlockProfileRecord struct
+pkg runtime, type BlockProfileRecord struct, Count int64
+pkg runtime, type BlockProfileRecord struct, Cycles int64
+pkg runtime, type BlockProfileRecord struct, embedded StackRecord

[dave_cheney.net, 2012-08-13 07:55:37]

This change is causing me to salivate. Do you have any measurements of any
performance overhead on semacquire/release when profiling is idle ?

http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/debug.go#newc...
src/pkg/runtime/debug.go:70: return r.Stack0[0:]
return r.Stack0 // no need to reslice.

http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/pprof/pprof.go
File src/pkg/runtime/pprof/pprof.go (right):

http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/pprof/pprof.g...
src/pkg/runtime/pprof/pprof.go:477: for i := range p {
for _, r := range p {

[dvyukov, 2012-08-13 08:06:59]

On Mon, Aug 13, 2012 at 10:55 AM, <dave@cheney.net> wrote:

> This change is causing me to salivate


:)
Vote for acceptance on the public list.



> Do you have any measurements of
> any performance overhead on semacquire/release when profiling is idle ?
>

No, I don't, but that only few untaken if's on slow-paths (when goroutine
blocking is involved anyway). So I don't think it's a problem.
I have some doubts about performance impact when profiling is enabled,
perhaps I need to do something similar to MemProfileRate.


http://codereview.appspot.com/**6443115/diff/1002/src/pkg/**runtime/debug.go<...
> File src/pkg/runtime/debug.go (right):
>
> http://codereview.appspot.com/**6443115/diff/1002/src/pkg/**
>
runtime/debug.go#newcode70<http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/debug.go#newcode70>
> src/pkg/runtime/debug.go:70: return r.Stack0[0:]
> return r.Stack0 // no need to reslice.
>

Is the array automatically converted to slice?


>
> http://codereview.appspot.com/**6443115/diff/1002/src/pkg/**
>
runtime/pprof/pprof.go<http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/pprof/pprof.go>
> File src/pkg/runtime/pprof/pprof.go (right):
>
> http://codereview.appspot.com/**6443115/diff/1002/src/pkg/**
>
runtime/pprof/pprof.go#**newcode477<http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/pprof/pprof.go#newcode477>
> src/pkg/runtime/pprof/pprof.**go:477: for i := range p {
> for _, r := range p {
>

Doesn't this involve struct copy?


The code is very dirty and must be rewritten, I just wanted to get a result
quickly while tracking down scalability problems in rpc/http while working
on the scheduler.
But I believe the ones you pointed out was copy-pasted from memprofiling.

[dave_cheney.net, 2012-08-13 08:13:47]

> Doesn't this involve struct copy?

In this case yes. As I was suggesting using the two arg form to avoid the bounds
check, it probably doesn't pay its way over copying 32 * uintptr.

[dave_cheney.net, 2012-08-13 08:14:03]

Ignore all my comments, you were correct.

http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/1002/src/pkg/runtime/debug.go#newc...
src/pkg/runtime/debug.go:70: return r.Stack0[0:]
On 2012/08/13 07:55:37, dfc wrote:
> return r.Stack0 // no need to reslice.

No they are not, your code is correct, but you can use r.Stack0[:].

[dvyukov, 2012-08-14 21:10:19]

Hello dave@cheney.net (cc: golang-dev@googlegroups.com),

I'd like you to review this change to
https://go.googlecode.com/hg/

[dave_cheney.net, 2012-08-15 07:15:53]

Thank you. I'm super excited to see this feature committed. Please review the
comments below, most are tab/space formatting issues.

http://codereview.appspot.com/6443115/diff/5/src/cmd/go/test.go
File src/cmd/go/test.go (right):

http://codereview.appspot.com/6443115/diff/5/src/cmd/go/test.go#newcode114
src/cmd/go/test.go:114: are complete.
nit: the name of the flag is a bit of a mouthful, but I can't think of anything
pithier off hand.

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go#newcode155
src/pkg/runtime/debug.go:155: Stack0 [32]uintptr
-Stack0 [32]uintptr
+StackRecord

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go#newcode159
src/pkg/runtime/debug.go:159: // a prefix of r.Stack0.
Then you can remove this

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/runtime.h
File src/pkg/runtime/runtime.h (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/runtime.h#newcod...
src/pkg/runtime/runtime.h:632: extern int32 runtime·ContentionProfileRate;
nit: formatting

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/sema.goc
File src/pkg/runtime/sema.goc (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/sema.goc#newcode29
src/pkg/runtime/sema.goc:29: int64 releasetime;
nit: formatting

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/sema.goc#newcode123
src/pkg/runtime/sema.goc:123: }
spaces/tabs

[dvyukov, 2012-08-15 09:52:36]

Updated API diff:

+pkg net/http/pprof, func ContentionProfileRate(http.ResponseWriter,
*http.Request)
+pkg runtime, func ContentionProfile([]ContentionProfileRecord) (int, bool)
+pkg runtime, method (*ContentionProfileRecord) Stack() []uintptr
+pkg runtime, type ContentionProfileRecord struct
+pkg runtime, type ContentionProfileRecord struct, Count int64
+pkg runtime, type ContentionProfileRecord struct, Cycles int64
+pkg runtime, type ContentionProfileRecord struct, embedded StackRecord
+pkg runtime, var ContentionProfileRate int

[dvyukov, 2012-08-15 09:55:45]

PTAL

http://codereview.appspot.com/6443115/diff/5/src/cmd/go/test.go
File src/cmd/go/test.go (right):

http://codereview.appspot.com/6443115/diff/5/src/cmd/go/test.go#newcode114
src/cmd/go/test.go:114: are complete.
On 2012/08/15 07:15:53, dfc wrote:
> nit: the name of the flag is a bit of a mouthful, but I can't think of
anything
> pithier off hand.

I can't think of a better name. It's not intended for everyday use, so I think
this name is OK (at least it is consistent with other names).

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go#newcode155
src/pkg/runtime/debug.go:155: Stack0 [32]uintptr
On 2012/08/15 07:15:53, dfc wrote:
> -Stack0 [32]uintptr
> +StackRecord

Done.

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go#newcode159
src/pkg/runtime/debug.go:159: // a prefix of r.Stack0.
On 2012/08/15 07:15:53, dfc wrote:
> Then you can remove this

Done.

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/runtime.h
File src/pkg/runtime/runtime.h (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/runtime.h#newcod...
src/pkg/runtime/runtime.h:632: extern int32 runtime·ContentionProfileRate;
On 2012/08/15 07:15:53, dfc wrote:
> nit: formatting 

It seems to be how vars are formatted here.

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/sema.goc
File src/pkg/runtime/sema.goc (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/sema.goc#newcode29
src/pkg/runtime/sema.goc:29: int64 releasetime;
On 2012/08/15 07:15:53, dfc wrote:
> nit: formatting

Done.

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/sema.goc#newcode123
src/pkg/runtime/sema.goc:123: }
On 2012/08/15 07:15:53, dfc wrote:
> spaces/tabs

These are tabs. It seems that codereview does not show tabs in new lines.

[dvyukov, 2012-08-15 10:03:32]

http://codereview.appspot.com/6443115/diff/2006/src/pkg/net/http/pprof/pprof.go
File src/pkg/net/http/pprof/pprof.go (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/net/http/pprof/pprof....
src/pkg/net/http/pprof/pprof.go:145: func ContentionProfileRate(w
http.ResponseWriter, r *http.Request) {
This is somewhat questionable.
The contention profiling is turned off be default (as opposed to mem profile),
so /debug/pprof/contention is useless as is. A user may provide own machinery to
control ContentionProfileRate, but that diminishes the purpose of
net/http/pprof.
Alternatively this handler can be made more general to control MemProfileRate as
well (and maybe something else).

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/debug.go#newc...
src/pkg/runtime/debug.go:148: var ContentionProfileRate int = 0
I am not 100% sure about this.
int32 in cycles allows to set max 1 event/sec. Since contention profiling is in
"goroutine time", 1 event/per may be still too frequent (e.g. each 1microsec of
real time).
We may change it to int64, but that somewhat inconsistent (and e.g. flags works
with ints).
Alternative we may measure rate in 1000cycles or microseconds.

[dave_cheney.net, 2012-08-15 10:17:27]

Looks good. Some minor comments.

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/5/src/pkg/runtime/debug.go#newcode159
src/pkg/runtime/debug.go:159: // a prefix of r.Stack0.
On 2012/08/15 09:55:45, dvyukov wrote:
> On 2012/08/15 07:15:53, dfc wrote:
> > Then you can remove this
> 
> Done.

I'm both surprised and pleased that this worked.

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/mprof.goc#new...
src/pkg/runtime/mprof.goc:281: runtime·contentionevent(int64 cycles)
Does this method show up in profiling (I understand this is a bit hard to test).

The stack allocation is pretty big, so I think it would stand a fair chance of
causing a stack split. I guess that is unavoidable.

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/pprof/sys_oth...
File src/pkg/runtime/pprof/sys_other.go (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/pprof/sys_oth...
src/pkg/runtime/pprof/sys_other.go:10: // TODO(dvyukov): not implemented.
OT: From experience the clock speed of devices I have seen Go deployed on runs
from 700mhz to 3.2ghz. What are the implications of this value being 50% wrong
sometimes ?

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/runtime.h
File src/pkg/runtime/runtime.h (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/runtime.h#new...
src/pkg/runtime/runtime.h:632: extern int32 runtime·ContentionProfileRate;
nit: still misaligned, this might be a code review issue.

[dvyukov, 2012-08-15 10:48:54]

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/mprof.goc#new...
src/pkg/runtime/mprof.goc:281: runtime·contentionevent(int64 cycles)
On 2012/08/15 10:17:28, dfc wrote:
> Does this method show up in profiling (I understand this is a bit hard to
test).

No, it does not. Bottom frames are sync.Mutex.Lock() or sync.WaitGroup.Wait().

> The stack allocation is pretty big, so I think it would stand a fair chance of
> causing a stack split. I guess that is unavoidable.

It's copied from mem profile. Theoretically the buffer can be moved to M, but I
think the way to control overhead is ContentionProfileRate.

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/pprof/sys_oth...
File src/pkg/runtime/pprof/sys_other.go (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/pprof/sys_oth...
src/pkg/runtime/pprof/sys_other.go:10: // TODO(dvyukov): not implemented.
On 2012/08/15 10:17:28, dfc wrote:
> OT: From experience the clock speed of devices I have seen Go deployed on runs
> from 700mhz to 3.2ghz. What are the implications of this value being 50% wrong
> sometimes ?

It is used merely to scale results.
The resulting profile (after pprof) says that this stack traces causes X seconds
of blocking. If the value is 50% wrong than X is 50% wrong.
However, the profiler measures blocking time in "goroutine time". So on net/http
tests that run for 5 seconds, some stack traces cause 300 seconds of blocking. I
mean that absolute values do not make a lot of sense anyway.

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/runtime.h
File src/pkg/runtime/runtime.h (right):

http://codereview.appspot.com/6443115/diff/2006/src/pkg/runtime/runtime.h#new...
src/pkg/runtime/runtime.h:632: extern int32 runtime·ContentionProfileRate;
On 2012/08/15 10:17:28, dfc wrote:
> nit: still misaligned, this might be a code review issue.

see the runtime·worldsema below.

[r, 2012-08-15 16:15:43]

On Wed, Aug 15, 2012 at 2:52 AM, Dmitry Vyukov <dvyukov@google.com> wrote:
> Updated API diff:
>
> +pkg net/http/pprof, func ContentionProfileRate(http.ResponseWriter,
> *http.Request)
> +pkg runtime, func ContentionProfile([]ContentionProfileRecord) (int, bool)
> +pkg runtime, method (*ContentionProfileRecord) Stack() []uintptr
> +pkg runtime, type ContentionProfileRecord struct
> +pkg runtime, type ContentionProfileRecord struct, Count int64
> +pkg runtime, type ContentionProfileRecord struct, Cycles int64
> +pkg runtime, type ContentionProfileRecord struct, embedded StackRecord
> +pkg runtime, var ContentionProfileRate int

I suggest not including this particular change in the CL. It's not a
problem to have a few functions appear in the all.bash output, plus it
may take a little time to converge on exactly what the changes should
be, even if/after this CL is committed.

Also, it's mostly an idiosyncrasy of mine, but I'd like the API tool
to be maintained by a separate, coarser process. If we bury all the
API changes in the CLs that create them, we're less aware of what's
changing.

-rob

[dvyukov, 2012-08-15 16:27:16]

On 2012/08/15 16:15:43, r wrote:
> On Wed, Aug 15, 2012 at 2:52 AM, Dmitry Vyukov <mailto:dvyukov@google.com>
wrote:
> > Updated API diff:
> >
> > +pkg net/http/pprof, func ContentionProfileRate(http.ResponseWriter,
> > *http.Request)
> > +pkg runtime, func ContentionProfile([]ContentionProfileRecord) (int, bool)
> > +pkg runtime, method (*ContentionProfileRecord) Stack() []uintptr
> > +pkg runtime, type ContentionProfileRecord struct
> > +pkg runtime, type ContentionProfileRecord struct, Count int64
> > +pkg runtime, type ContentionProfileRecord struct, Cycles int64
> > +pkg runtime, type ContentionProfileRecord struct, embedded StackRecord
> > +pkg runtime, var ContentionProfileRate int
> 
> I suggest not including this particular change in the CL. It's not a
> problem to have a few functions appear in the all.bash output, plus it
> may take a little time to converge on exactly what the changes should
> be, even if/after this CL is committed.
> 
> Also, it's mostly an idiosyncrasy of mine, but I'd like the API tool
> to be maintained by a separate, coarser process. If we bury all the
> API changes in the CLs that create them, we're less aware of what's
> changing.

OK.

[dvyukov, 2012-08-19 08:58:52]

Added a fix that removes uninteresting users of semaphores from the profile. In
particular I've seen stoptheworld semaphore (GC) in profiles, it confuses.

[dvyukov, 2012-08-19 09:19:11]

Added chan blocking profiling.

[remyoudompheng, 2012-08-19 09:26:18]

On 2012/08/19 08:58:52, dvyukov wrote:
> Added a fix that removes uninteresting users of semaphores from the profile.
In
> particular I've seen stoptheworld semaphore (GC) in profiles, it confuses.

Are you sure it is a good idea? having a comparison between wait times due to GC
pauses and lock contention seems valuable to me. I could be reluctant to
optimizing lock contention if I discover the GC pauses 2 seconds every 20
seconds and causes most of the inefficiencies. What do you think?

[dvyukov, 2012-08-19 09:54:47]

On Sun, Aug 19, 2012 at 1:26 PM, <remyoudompheng@gmail.com> wrote:

> On 2012/08/19 08:58:52, dvyukov wrote:
>
>> Added a fix that removes uninteresting users of semaphores from the
>>
> profile. In
>
>> particular I've seen stoptheworld semaphore (GC) in profiles, it
>>
> confuses.
>
> Are you sure it is a good idea? having a comparison between wait times
> due to GC pauses and lock contention seems valuable to me. I could be
> reluctant to optimizing lock contention if I discover the GC pauses 2
> seconds every 20 seconds and causes most of the inefficiencies. What do
> you think?
>


Contention profiling is useful mostly to track down CPU underutilization
problems (not enough runnable goroutines to occupy all CPUs), GC is
sufficiently parallel itself and so it does not add to CPU underutilization.
I can imagine cases where contention profiling is used to track down
latency issues (all CPUs are busy, but some requests take too long to
complete). In this case GC indeed adds. There are 2 points. First, there
are already some profiling capabilities for GC (that have beed successfully
using for latency issues). Second, if it's integrated into contention
profiling, then single semacquire won't do, because it's called only on
some paths for some goroutines. The support must be more fundamental, for
now it's better to just disable that single call.

[dvyukov, 2012-08-19 10:27:56]

Added ContentionProfileRate support.

[dvyukov, 2012-08-19 10:28:10]

On 2012/08/19 09:19:11, dvyukov wrote:
> Added chan blocking profiling.

no select's for now

[gobot, 2012-08-31 20:01:07]

R=rsc (assigned by rsc)

[dave_cheney.net, 2012-09-11 00:49:59]

ping.

[rsc, 2012-09-17 21:08:07]

Overall seems okay but there are things to clean up.

http://codereview.appspot.com/6443115/diff/7026/src/cmd/go/test.go
File src/cmd/go/test.go (right):

http://codereview.appspot.com/6443115/diff/7026/src/cmd/go/test.go#newcode112
src/cmd/go/test.go:112: -test.contentionprofile cont.out
Can we shorten contention to something? We write mem not memory. You have to
invoke the binary by hand to get these so you're talking about a 23-byte flag.

lockprofile?
blockprofile?

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/mprof.goc#new...
src/pkg/runtime/mprof.goc:290: if(rate > cycles && runtime·fastrand1()%rate >
cycles)
Is this correct sampling?

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/pprof/sys_lin...
File src/pkg/runtime/pprof/sys_linux.go (right):

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/pprof/sys_lin...
src/pkg/runtime/pprof/sys_linux.go:13: c = 2e9 // wild guess
This needs to be fixed before submit.

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/pprof/sys_oth...
File src/pkg/runtime/pprof/sys_other.go (right):

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/pprof/sys_oth...
src/pkg/runtime/pprof/sys_other.go:10: // TODO(dvyukov): not implemented.
This needs to be fixed before submit.
Maybe it should be cpu-specific code instead of OS-specific code.
I would expect a cputickfreq function to live next to cputicks so that
they are in sync.

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/sema.goc
File src/pkg/runtime/sema.goc (right):

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/sema.goc#newc...
src/pkg/runtime/sema.goc:27: uint32 volatile*	addr;
You don't have to undo these, but in the future please avoid spacing changes
like this. They clutter the diffs.

[dave_cheney.net, 2012-09-18 17:19:49]

Can you please remail this, it doesn't apply cleanly any more.

Also, there may be a problem with an additional dependency (io/ioutil), which
causes pkg/go/build/deps_test.go to fail.

[dvyukov, 2012-09-18 19:49:10]

On Mon, Sep 17, 2012 at 2:08 PM, <rsc@golang.org> wrote:

> Overall seems okay but there are things to clean up.
>
>
http://codereview.appspot.com/**6443115/diff/7026/src/cmd/go/**test.go<http:/...
> File src/cmd/go/test.go (right):
>
> http://codereview.appspot.com/**6443115/diff/7026/src/cmd/go/**
>
test.go#newcode112<http://codereview.appspot.com/6443115/diff/7026/src/cmd/go/test.go#newcode112>
> src/cmd/go/test.go:112: -test.contentionprofile cont.out
> Can we shorten contention to something? We write mem not memory. You
> have to invoke the binary by hand to get these so you're talking about a
> 23-byte flag.
>
> lockprofile?
> blockprofile?
>

I like blockprofile.
Do you mean I replace contention->block everywhere, or just the flag name?

[rsc, 2012-09-18 19:54:25]

I meant just the flag name but probably the other API names should match.

[dvyukov, 2012-09-18 20:27:23]

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

http://codereview.appspot.com/6443115/diff/7026/src/pkg/runtime/mprof.goc#new...
src/pkg/runtime/mprof.goc:290: if(rate > cycles && runtime·fastrand1()%rate >
cycles)
On 2012/09/17 21:08:07, rsc wrote:
> Is this correct sampling?

Well, there may be better sampling techniques. But this is simple enough and
filters proportionally to blocking time.

[dvyukov, 2012-09-18 21:06:39]

On 2012/09/18 17:19:49, dfc wrote:
> Can you please remail this, it doesn't apply cleanly any more.

Done
Do you use it? What is your experience?

[dave_cheney.net, 2012-09-18 21:10:28]

I haven't had a case to use it apart from the issues that you raised
for the net and http packages. I would like to try it on the
go.crypto/ssh package and the tls pacakges, to see if contention (as
opposed to crypto) is a significant % of the runtime.

On Wed, Sep 19, 2012 at 7:06 AM,  <dvyukov@google.com> wrote:
> On 2012/09/18 17:19:49, dfc wrote:
>>
>> Can you please remail this, it doesn't apply cleanly any more.
>
>
> Done
> Do you use it? What is your experience?
>
>
> http://codereview.appspot.com/6443115/

[dvyukov, 2012-09-18 21:28:41]

http://codereview.appspot.com/6443115/diff/27013/src/pkg/runtime/runtime.c
File src/pkg/runtime/runtime.c (right):

http://codereview.appspot.com/6443115/diff/27013/src/pkg/runtime/runtime.c#ne...
src/pkg/runtime/runtime.c:363: runtime∕pprof·runtime_cyclesPerSecond(int64 res)
How about this?

On my machine where /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq says
2395000000, this method says:
2393915609
2393927695
2393923912

It is portable and allows to remove that pprof/sys_* files, and removes the
additional dependency between runtime/pprof->io/ioutil as well.

The more precise method would require either to examine CPUID output (it's quite
tricky, works since Pentium4 and I am not sure about AMD). I have no idea how to
do it on ARM. Or alternatively, OS-dependent method is to read it from system
registry on Windows, and I don't know about other OSes.

[dave_cheney.net, 2012-09-18 21:32:59]

I don't know if that will be reliable enough. Even with the performance governor
enabled, the CPU freq on my i5 shifts between 2.5 and 3.0 Ghz depending on
thermal load. Additionally for some systems C state sleeping may not be
optional, which will throw this computation off as well.

[dvyukov, 2012-09-18 21:34:48]

I would expect TSC to tick with constant freq regardless of TurboBoost and
C states.


On Tue, Sep 18, 2012 at 2:33 PM, <dave@cheney.net> wrote:

> I don't know if that will be reliable enough. Even with the performance
> governor enabled, the CPU freq on my i5 shifts between 2.5 and 3.0 Ghz
> depending on thermal load. Additionally for some systems C state
> sleeping may not be optional, which will throw this computation off as
> well.
>
>
http://codereview.appspot.com/**6443115/<http://codereview.appspot.com/6443115/>
>

[dvyukov, 2012-09-18 21:36:08]

Otherwise I would prefer to drop this at all, pprof assumes 2GHz by default
which should be enough.


On Tue, Sep 18, 2012 at 2:34 PM, Dmitry Vyukov <dvyukov@google.com> wrote:

> I would expect TSC to tick with constant freq regardless of TurboBoost and
> C states.
>
>
>
> On Tue, Sep 18, 2012 at 2:33 PM, <dave@cheney.net> wrote:
>
>> I don't know if that will be reliable enough. Even with the performance
>> governor enabled, the CPU freq on my i5 shifts between 2.5 and 3.0 Ghz
>> depending on thermal load. Additionally for some systems C state
>> sleeping may not be optional, which will throw this computation off as
>> well.
>>
>>
http://codereview.appspot.com/**6443115/<http://codereview.appspot.com/6443115/>
>>
>
>

[dvyukov, 2012-09-18 22:16:59]

On 2012/09/18 19:54:25, rsc wrote:
> I meant just the flag name but probably the other API names should match.

Renamed Contention->Block everywhere.
New API diff:
+pkg net/http/pprof, func BlockProfileRate(http.ResponseWriter, *http.Request)
+pkg runtime, func BlockProfile([]BlockProfileRecord) (int, bool)
+pkg runtime, method (*BlockProfileRecord) Stack() []uintptr
+pkg runtime, type BlockProfileRecord struct
+pkg runtime, type BlockProfileRecord struct, Count int64
+pkg runtime, type BlockProfileRecord struct, Cycles int64
+pkg runtime, type BlockProfileRecord struct, embedded StackRecord
+pkg runtime, var BlockProfileRate int
PTAL

[minux1, 2012-09-19 09:25:59]

http://codereview.appspot.com/6443115/diff/27013/src/pkg/runtime/runtime.c
File src/pkg/runtime/runtime.c (right):

http://codereview.appspot.com/6443115/diff/27013/src/pkg/runtime/runtime.c#ne...
src/pkg/runtime/runtime.c:363: runtime∕pprof·runtime_cyclesPerSecond(int64 res)
On 2012/09/18 21:28:42, dvyukov wrote:
> How about this?
won't work on ARM.
Linux/ARM doesn't allow user space access to the cycle counter.

so runtime.cputicks() on ARM actually returns a random number
(for seeding our hash map)

> The more precise method would require either to examine CPUID output (it's
quite
> tricky, works since Pentium4 and I am not sure about AMD). I have no idea how
to
> do it on ARM. Or alternatively, OS-dependent method is to read it from system
> registry on Windows, and I don't know about other OSes.
I think the best way is to get it from the OS.

[rsc, 2012-09-20 18:47:36]

LGTM

Please wait for r to take a look at the new API + testing flags too.

[r, 2012-09-20 18:57:57]

http://codereview.appspot.com/6443115/diff/36001/src/cmd/go/test.go
File src/cmd/go/test.go (right):

http://codereview.appspot.com/6443115/diff/36001/src/cmd/go/test.go#newcode119
src/cmd/go/test.go:119: aims to sample an average of one blocking event per that
many
s/that many/n/
or else i don't understand this comment

http://codereview.appspot.com/6443115/diff/36001/src/cmd/go/test.go#newcode120
src/cmd/go/test.go:120: CPU cycles.  By default all blocking events are
recorded.
by default, what is the value of n?
i guess i don't understand this comment.

http://codereview.appspot.com/6443115/diff/36001/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

http://codereview.appspot.com/6443115/diff/36001/src/pkg/runtime/debug.go#new...
src/pkg/runtime/debug.go:144: // one blocking event per BlockProfileRate CPU
cycles.
i'm still confused. i don't see how blocking events and CPU cycles are related.
sorry to be so dim.

http://codereview.appspot.com/6443115/diff/36001/src/pkg/runtime/debug.go#new...
src/pkg/runtime/debug.go:148: var BlockProfileRate int = 0
an int with the value of 0 or 1 sounds like a bool to me.

[rsc, 2012-09-20 19:47:15]

time spent blocking is measured in cpu cycles (perhaps confusingly)
if the rate is set to 1000 then it tries to sample one blocking event
per 1000 cpu cycles spent blocked.

probably the rate and the output should be in nanoseconds or something
more portable.

[dvyukov, 2012-09-20 20:01:29]

https://codereview.appspot.com/6443115/diff/36001/src/cmd/go/test.go
File src/cmd/go/test.go (right):

https://codereview.appspot.com/6443115/diff/36001/src/cmd/go/test.go#newcode120
src/cmd/go/test.go:120: CPU cycles.  By default all blocking events are
recorded.
On 2012/09/20 18:57:58, r wrote:
> by default, what is the value of n?
> i guess i don't understand this comment.

The default value of n is 1.

https://codereview.appspot.com/6443115/diff/36001/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

https://codereview.appspot.com/6443115/diff/36001/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:148: var BlockProfileRate int = 0
On 2012/09/20 18:57:58, r wrote:
> an int with the value of 0 or 1 sounds like a bool to me.

The intention is the same as with MemProfileRate:

n<=0 - turn off the profiler
n=1 - record every blocking event
n>1 - sample some fraction of events: if we have a blocking event of duration x
CPU cycles, then it's sampled with probability min(1, x/n). So on average it's
one blocking event per n CPU cycles of... total blocking events.

I think the process will be faster, if you propose your wording (if I succeed in
explaining the intention).

[dvyukov, 2012-09-20 20:11:07]

On 2012/09/20 19:47:15, rsc wrote:
> time spent blocking is measured in cpu cycles (perhaps confusingly)
> if the rate is set to 1000 then it tries to sample one blocking event
> per 1000 cpu cycles spent blocked.
> 
> probably the rate and the output should be in nanoseconds or something
> more portable.

pprof expects input in cycles, pprof output is in seconds. This part looks fine.

potentially BlockProfileRace may be measured in nanoseconds, but then I need to
convert ns to cycles somewhere... I think it can be easily done in
runtime·blockevent() (mprof.goc).

[rsc, 2012-09-20 20:12:52]

> potentially BlockProfileRace may be measured in nanoseconds, but then I
> need to convert ns to cycles somewhere... I think it can be easily done
> in runtime·blockevent() (mprof.goc).

That's fine, but given that we can't even agree on how well to define
cycles, they should be an internal detail. The API exposed by package
runtime should talk about nanoseconds.

Russ

[dvyukov, 2012-09-20 20:14:02]

On Thu, Sep 20, 2012 at 1:12 PM, Russ Cox <rsc@golang.org> wrote:

> > potentially BlockProfileRace may be measured in nanoseconds, but then I
> > need to convert ns to cycles somewhere... I think it can be easily done
> > in runtime·blockevent() (mprof.goc).
>
> That's fine, but given that we can't even agree on how well to define
> cycles, they should be an internal detail. The API exposed by package
> runtime should talk about nanoseconds.
>

OK, I will change it to ns.

[dvyukov, 2012-09-20 22:31:10]

PTAL

Now BlockProfileRate is in ns.
Fixed comments.
Added runtime·tickspersecond(void), it caches the value so it is stable during
execution.

[r, 2012-09-21 04:50:02]

Now I'm bothered by the idea of a rate being measure in units of time rather
than frequency. Sorry. I know it's analogous with the memory one but that didn't
have units of time, so the rate/time thing didn't stick out.

But I don't have a better idea, so maybe this will stand. Wording will help.
I'll work on that.

[r, 2012-09-21 04:57:37]

https://codereview.appspot.com/6443115/diff/37006/src/cmd/go/test.go
File src/cmd/go/test.go (right):

https://codereview.appspot.com/6443115/diff/37006/src/cmd/go/test.go#newcode120
src/cmd/go/test.go:120: spent blocked.  By default all blocking events are
recorded.
Control the detail provided in goroutine blocking profiles by setting
runtime.BlockProfileRate to n. See 'godoc runtime BlockProfileRate'.
The profiler aims to sample, on average, one blocking event every
n nanoseconds the program (or is it a goroutine??) spends blocked. By
default, if -test.blockprofile is set without this flag, all blocking events
are recorded, equivalent to -testblockprofile=1.

https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:142: // that are recorded and reported in the blocking
profile.
s/recorded and// (it's redundant)

https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:144: // one blocking event per BlockProfileRate
nanoseconds spent blocked.
what does blocked mean? is it global, goroutine, mutex, channel...?

[rsc, 2012-09-21 05:06:12]

> src/pkg/runtime/debug.go:144: // one blocking event per BlockProfileRate
> nanoseconds spent blocked.
> what does blocked mean? is it global, goroutine, mutex, channel...?

it's a random sampling rate, so it's not per-anything.
each time something gets blocked there is a chance
it will be sampled.

[dvyukov, 2012-09-22 03:51:57]

PTAL

https://codereview.appspot.com/6443115/diff/37006/src/cmd/go/test.go
File src/cmd/go/test.go (right):

https://codereview.appspot.com/6443115/diff/37006/src/cmd/go/test.go#newcode120
src/cmd/go/test.go:120: spent blocked.  By default all blocking events are
recorded.
On 2012/09/21 04:57:37, r wrote:
> Control the detail provided in goroutine blocking profiles by setting
> runtime.BlockProfileRate to n. See 'godoc runtime BlockProfileRate'.
> The profiler aims to sample, on average, one blocking event every
> n nanoseconds the program (or is it a goroutine??)

It is per program.

> spends blocked. By
> default, if -test.blockprofile is set without this flag, all blocking events
> are recorded, equivalent to -testblockprofile=1.

Done.

https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:142: // that are recorded and reported in the blocking
profile.
On 2012/09/21 04:57:37, r wrote:
> s/recorded and// (it's redundant)

Done.

https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:144: // one blocking event per BlockProfileRate
nanoseconds spent blocked.
On 2012/09/21 04:57:37, r wrote:
> what does blocked mean? is it global, goroutine, mutex, channel...?

Blocking event is when a goroutine blocks on mutex/channel/waitgroup/etc.

[dvyukov, 2012-09-26 21:49:28]

Is it OK to submit now?

On 2012/09/22 03:51:57, dvyukov wrote:
> PTAL
> 
> https://codereview.appspot.com/6443115/diff/37006/src/cmd/go/test.go
> File src/cmd/go/test.go (right):
> 
>
https://codereview.appspot.com/6443115/diff/37006/src/cmd/go/test.go#newcode120
> src/cmd/go/test.go:120: spent blocked.  By default all blocking events are
> recorded.
> On 2012/09/21 04:57:37, r wrote:
> > Control the detail provided in goroutine blocking profiles by setting
> > runtime.BlockProfileRate to n. See 'godoc runtime BlockProfileRate'.
> > The profiler aims to sample, on average, one blocking event every
> > n nanoseconds the program (or is it a goroutine??)
> 
> It is per program.
> 
> > spends blocked. By
> > default, if -test.blockprofile is set without this flag, all blocking events
> > are recorded, equivalent to -testblockprofile=1.
> 
> Done.
> 
> https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go
> File src/pkg/runtime/debug.go (right):
> 
>
https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go#ne...
> src/pkg/runtime/debug.go:142: // that are recorded and reported in the
blocking
> profile.
> On 2012/09/21 04:57:37, r wrote:
> > s/recorded and// (it's redundant)
> 
> Done.
> 
>
https://codereview.appspot.com/6443115/diff/37006/src/pkg/runtime/debug.go#ne...
> src/pkg/runtime/debug.go:144: // one blocking event per BlockProfileRate
> nanoseconds spent blocked.
> On 2012/09/21 04:57:37, r wrote:
> > what does blocked mean? is it global, goroutine, mutex, channel...?
> 
> Blocking event is when a goroutine blocks on mutex/channel/waitgroup/etc.

[minux1, 2012-09-27 09:39:30]

On 2012/09/26 21:49:28, dvyukov wrote:
> Is it OK to submit now?
The only problem is that this feature is completely unusable
on ARM due to lack of correct runtime.cputicks().

I suggest you document this as a known BUG.

[dvyukov, 2012-09-27 18:53:32]

Can't we use nanotime() or something like that on ARM? It may be slower,
but still better than nothing. The profiler does not care too much that the
cpu ticks are actually cpu ticks, it just needs some relatively precise
time source.



On Thu, Sep 27, 2012 at 2:39 AM, <minux.ma@gmail.com> wrote:

> On 2012/09/26 21:49:28, dvyukov wrote:
>
>> Is it OK to submit now?
>>
> The only problem is that this feature is completely unusable
> on ARM due to lack of correct runtime.cputicks().
>
> I suggest you document this as a known BUG.
>
>
https://codereview.appspot.**com/6443115/<https://codereview.appspot.com/6443...
>

[dave_cheney.net, 2012-09-29 04:32:23]

Let's try with nanotime() on arm in the spirit of getting this in.

[dvyukov, 2012-10-01 13:18:10]

PTAL
I've made cputicks() use nanotime() on arm.

https://codereview.appspot.com/6443115/diff/54001/src/pkg/runtime/signal_linu...
File src/pkg/runtime/signal_linux_arm.c (right):

https://codereview.appspot.com/6443115/diff/54001/src/pkg/runtime/signal_linu...
src/pkg/runtime/signal_linux_arm.c:209: return runtime·nanotime() +
runtime·randomNumber;
Does it look fine?
It replaces pseudo-random sequence with nanotime(). It is not worse for seeding
fastrand1, because the pseudo-random sequence is easily predictable as well.

[minux1, 2012-10-01 15:30:07]

LGTM.

https://codereview.appspot.com/6443115/diff/54001/src/pkg/runtime/signal_linu...
File src/pkg/runtime/signal_linux_arm.c (right):

https://codereview.appspot.com/6443115/diff/54001/src/pkg/runtime/signal_linu...
src/pkg/runtime/signal_linux_arm.c:208: runtime·cputicks() {
could you please add some comments here to explain why this function does this?

I think this approach is good, but might confuse future readers.

[minux1, 2012-10-01 15:30:23]

LGTM.

[dvyukov, 2012-10-01 15:46:45]

PTAL

https://codereview.appspot.com/6443115/diff/54001/src/pkg/runtime/signal_linu...
File src/pkg/runtime/signal_linux_arm.c (right):

https://codereview.appspot.com/6443115/diff/54001/src/pkg/runtime/signal_linu...
src/pkg/runtime/signal_linux_arm.c:208: runtime·cputicks() {
On 2012/10/01 15:30:07, minux wrote:
> could you please add some comments here to explain why this function does
this?
> 
> I think this approach is good, but might confuse future readers.

Done.

[minux1, 2012-10-01 15:50:32]

LGTM. (seems Chrome already foreseen this and sent one earlier.)

[dvyukov, 2012-10-01 15:52:25]

On 2012/10/01 15:50:32, minux wrote:
> LGTM. (seems Chrome already foreseen this and sent one earlier.)

OK, let's wait for one more Russ LGTM.

[minux1, 2012-10-01 16:01:43]

Please update CL description (roughly s/Contention/Block(ing)/).

[rsc, 2012-10-01 20:11:20]

https://codereview.appspot.com/6443115/diff/61005/src/pkg/net/http/pprof/ppro...
File src/pkg/net/http/pprof/pprof.go (right):

https://codereview.appspot.com/6443115/diff/61005/src/pkg/net/http/pprof/ppro...
src/pkg/net/http/pprof/pprof.go:151: // BlockProfileRate gets or sets
runtime.BlockProfileRate.
I don't think this belongs here. We don't have http handlers to set the other
profiling rates. We might want to do that, but it should be a designed approach
and not piecemeal. Please remove this handler.

https://codereview.appspot.com/6443115/diff/61005/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

https://codereview.appspot.com/6443115/diff/61005/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:147: var BlockProfileRate int = 0
Should this be just SetBlockProfileRate, like we have SetCPUProfileRate above?

[dvyukov, 2012-10-02 05:54:20]

On 2012/10/01 16:01:43, minux wrote:
> Please update CL description (roughly s/Contention/Block(ing)/).

Done.

[dvyukov, 2012-10-02 05:57:56]

PTAL

https://codereview.appspot.com/6443115/diff/61005/src/pkg/net/http/pprof/ppro...
File src/pkg/net/http/pprof/pprof.go (right):

https://codereview.appspot.com/6443115/diff/61005/src/pkg/net/http/pprof/ppro...
src/pkg/net/http/pprof/pprof.go:151: // BlockProfileRate gets or sets
runtime.BlockProfileRate.
On 2012/10/01 20:11:20, rsc wrote:
> I don't think this belongs here. We don't have http handlers to set the other
> profiling rates. We might want to do that, but it should be a designed
approach
> and not piecemeal. Please remove this handler.
> 

Done.

https://codereview.appspot.com/6443115/diff/61005/src/pkg/runtime/debug.go
File src/pkg/runtime/debug.go (right):

https://codereview.appspot.com/6443115/diff/61005/src/pkg/runtime/debug.go#ne...
src/pkg/runtime/debug.go:147: var BlockProfileRate int = 0
On 2012/10/01 20:11:20, rsc wrote:
> Should this be just SetBlockProfileRate, like we have SetCPUProfileRate above?

Done.

[rsc, 2012-10-05 20:16:00]

LGTM

Thanks for your patience.

[dvyukov, 2012-10-06 08:56:45]

*** Submitted as http://code.google.com/p/go/source/detail?r=b19c6b32c8da ***

pprof: add goroutine blocking profiling
The profiler collects goroutine blocking information similar to Google Perf
Tools.
You may see an example of the profile (converted to svg) attached to
http://code.google.com/p/go/issues/detail?id=3946
The public API changes are:
+pkg runtime, func BlockProfile([]BlockProfileRecord) (int, bool)
+pkg runtime, func SetBlockProfileRate(int)
+pkg runtime, method (*BlockProfileRecord) Stack() []uintptr
+pkg runtime, type BlockProfileRecord struct
+pkg runtime, type BlockProfileRecord struct, Count int64
+pkg runtime, type BlockProfileRecord struct, Cycles int64
+pkg runtime, type BlockProfileRecord struct, embedded StackRecord

R=rsc, dave, minux.ma, r
CC=gobot, golang-dev, r, remyoudompheng
http://codereview.appspot.com/6443115