code review 50420043: runtime: output how long goroutines are blocked

runtime: output how long goroutines are blocked
Example of output:

goroutine 4 [sleep for 3 min]:
time.Sleep(0x34630b8a000)
        src/pkg/runtime/time.goc:31 +0x31
main.func·002()
        block.go:16 +0x2c
created by main.main
        block.go:17 +0x33

Full program and output are here:
http://play.golang.org/p/NEZdADI3Td

Fixes issue 6809.

[dvyukov, 2014-01-10 11:44:53]

Hello golang-codereviews@googlegroups.com,

I'd like you to review this change to
https://dvyukov%40google.com@code.google.com/p/go/

[khr, 2014-01-10 19:05:24]

LGTM.

https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/mgc0.c
File src/pkg/runtime/mgc0.c (right):

https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/mgc0.c#new...
src/pkg/runtime/mgc0.c:1681: // needed only to output in traceback
Can't you fold this code into the switch above?

[kisielk, 2014-01-10 20:00:07]

Is there a particular reason you chose to have the resolution in minutes instead
of seconds?

[dvyukov, 2014-01-11 10:49:16]

On Sat, Jan 11, 2014 at 12:00 AM,  <kamil.kisiel@gmail.com> wrote:
> Is there a particular reason you chose to have the resolution in minutes
> instead of seconds?
>
> https://codereview.appspot.com/50420043/

There are several reasons for this:
1. I remember the time when a goroutine becomes blocked only during
GC, so there is significant error in this value (if we measure it in
seconds).
2. Most likely you don't care about blocking for several seconds.
3. Most likely you are interested in goroutines blocked for more than
few minutes. If we output it in seconds then it will make values
larger and more difficult to quickly analyze.
4. I don't want complex formatting in runtime.
Minutes looks like a very reasonable choice for me.

[dvyukov, 2014-01-13 07:08:53]

https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/mgc0.c
File src/pkg/runtime/mgc0.c (right):

https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/mgc0.c#new...
src/pkg/runtime/mgc0.c:1681: // needed only to output in traceback
On 2014/01/10 19:05:24, khr wrote:
> Can't you fold this code into the switch above?

I think that the current code is easier to understand and maintain than if I try
to fit into the switch. First the switch merges Grunnable/Gsyscall/Gwaiting, so
I still will need to add if on status (which is weird when we are already in the
status switch). Second, the the switch and my if are doing completely different
logical tasks, and the conditions for them will be changing independently.

[dvyukov, 2014-01-13 07:10:20]

Anybody else?
Any comments on the output format -- just appending " for 3 min" to status?

[bradfitz, 2014-01-13 07:12:08]

Maybe you have to ask golang-dev.
 On Jan 12, 2014 11:10 PM, <dvyukov@google.com> wrote:

> Anybody else?
> Any comments on the output format -- just appending " for 3 min" to
> status?
>
> https://codereview.appspot.com/50420043/
>
> --
> You received this message because you are subscribed to the Google Groups
> "golang-codereviews" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to golang-codereviews+unsubscribe@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>

[rsc, 2014-01-13 16:31:41]

LGTM

https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/proc.c
File src/pkg/runtime/proc.c (right):

https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/proc.c#new...
src/pkg/runtime/proc.c:273: runtime·printf("goroutine %D [%s for %D min]:\n",
gp->goid, status, waitfor);
drop the for entirely. and spell out min so it's not "minimum".

[%s, %D minutes]

[dvyukov, 2014-01-16 08:53:09]

On 2014/01/13 16:31:41, rsc wrote:
> LGTM
> 
> https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/proc.c
> File src/pkg/runtime/proc.c (right):
> 
>
https://codereview.appspot.com/50420043/diff/60001/src/pkg/runtime/proc.c#new...
> src/pkg/runtime/proc.c:273: runtime·printf("goroutine %D [%s for %D min]:\n",
> gp->goid, status, waitfor);
> drop the for entirely. and spell out min so it's not "minimum".
> 
> [%s, %D minutes]

Done

[dvyukov, 2014-01-16 08:58:40]

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

runtime: output how long goroutines are blocked
Example of output:

goroutine 4 [sleep for 3 min]:
time.Sleep(0x34630b8a000)
        src/pkg/runtime/time.goc:31 +0x31
main.func·002()
        block.go:16 +0x2c
created by main.main
        block.go:17 +0x33

Full program and output are here:
http://play.golang.org/p/NEZdADI3Td

Fixes issue 6809.

R=golang-codereviews, khr, kamil.kisiel, bradfitz, rsc
CC=golang-codereviews
https://codereview.appspot.com/50420043