code review 21990045: runtime: add an allocation and free tracing for gc debugging

runtime: add an allocation and free tracing for gc debugging

Output for an allocation and free (sweep) follows

MProf_Malloc(p=0xc2100210a0, size=0x50, type=0x0 <single object>)
        #0 0x46ee15 runtime.mallocgc /usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:141
        #1 0x47004f runtime.settype_flush /usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:612
        #2 0x45f92c gc /usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2071
        #3 0x45f89e mgc /usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2050
        #4 0x45258b runtime.mcall /usr/local/google/home/cshapiro/go/src/pkg/runtime/asm_amd64.s:179

MProf_Free(p=0xc2100210a0, size=0x50)
        #0 0x46ee15 runtime.mallocgc /usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:141
        #1 0x47004f runtime.settype_flush /usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:612
        #2 0x45f92c gc /usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2071
        #3 0x45f89e mgc /usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2050
        #4 0x45258b runtime.mcall /usr/local/google/home/cshapiro/go/src/pkg/runtime/asm_amd64.s:179

[cshapiro, 2013-11-12 21:58:06]

Hello golang-dev@googlegroups.com,

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

[dvyukov, 2013-11-14 08:26:45]

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/malloc.goc
File src/pkg/runtime/malloc.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/malloc.goc...
src/pkg/runtime/malloc.goc:125: if(runtime·debug.allocfreetrace)
can we have this as enum as well?

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc#...
src/pkg/runtime/mprof.goc:298: name = typeinfoname(typ & 3);
please move this under if(runtime·debug.allocfreetrace)
the profiler is enabled by default in production

[cshapiro, 2013-11-14 21:32:17]

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/malloc.goc
File src/pkg/runtime/malloc.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/malloc.goc...
src/pkg/runtime/malloc.goc:125: if(runtime·debug.allocfreetrace)
I'm not seeing this show up in a time profile.  Let's continue this discussion
in the other change where you have raised the same issue.  (I think this case is
less severe since it is already in a slow path.)

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc#...
src/pkg/runtime/mprof.goc:298: name = typeinfoname(typ & 3);
Good idea, considering the compiler we are using.  Done.

[rsc, 2013-11-15 17:02:12]

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc#...
src/pkg/runtime/mprof.goc:298: name = typeinfoname(typ & 3);
On 2013/11/14 21:32:18, cshapiro wrote:
> Good idea, considering the compiler we are using.  Done.

What does this mean? It sounds like you are saying the compiler is not doing
something that it should be, but I can't see what that something would be.

Also, you said "Done" but I don't see a newer version of the CL.

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/extern.go
File src/pkg/runtime/extern.go (right):

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/extern.go#...
src/pkg/runtime/extern.go:40: profiled and a stack trace printed on each objects
allocation and free.
s/objects/object's/

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

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/runtime.c#...
src/pkg/runtime/runtime.c:393: {"allocfreetrace",
&runtime·debug.allocfreetrace},
please sort this list
(it was not quite sorted before)

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/runtime.h
File src/pkg/runtime/runtime.h (right):

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/runtime.h#...
src/pkg/runtime/runtime.h:536: int32	gctrace;
please sort this list too

[cshapiro1, 2013-11-15 21:09:00]

PTAL

[cshapiro1, 2013-11-15 21:09:10]

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/extern.go
File src/pkg/runtime/extern.go (right):

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/extern.go#...
src/pkg/runtime/extern.go:40: profiled and a stack trace printed on each objects
allocation and free.
On 2013/11/15 17:02:12, rsc wrote:
> s/objects/object's/

Done.

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

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/runtime.c#...
src/pkg/runtime/runtime.c:393: {"allocfreetrace",
&runtime·debug.allocfreetrace},
On 2013/11/15 17:02:12, rsc wrote:
> please sort this list
> (it was not quite sorted before)

Done.

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/runtime.h
File src/pkg/runtime/runtime.h (right):

https://codereview.appspot.com/21990045/diff/60001/src/pkg/runtime/runtime.h#...
src/pkg/runtime/runtime.h:536: int32	gctrace;
On 2013/11/15 17:02:12, rsc wrote:
> please sort this list too

Done.

[cshapiro, 2013-11-15 21:44:37]

No idea why this comment was held back...

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc#...
src/pkg/runtime/mprof.goc:298: name = typeinfoname(typ & 3);
On 2013/11/15 17:02:12, rsc wrote:
> What does this mean? It sounds like you are saying the compiler is not doing
> something that it should be, but I can't see what that something would be.

Pushing code into a more control dependent region.

> Also, you said "Done" but I don't see a newer version of the CL.

Sorry, I am not sure what happened there.  I still have the original "hg upload"
in a terminal window.  I have re-uploaded and it claims it's there now.

[rsc, 2013-11-16 16:38:34]

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/40001/src/pkg/runtime/mprof.goc#...
src/pkg/runtime/mprof.goc:298: name = typeinfoname(typ & 3);
On 2013/11/15 21:44:37, cshapiro wrote:
> On 2013/11/15 17:02:12, rsc wrote:
> > What does this mean? It sounds like you are saying the compiler is not doing
> > something that it should be, but I can't see what that something would be.
> 
> Pushing code into a more control dependent region.

No compiler could do that. typeinfoname is not a pure function. It might call
runtime.throw. Moving it into the if statement would incorrectly remove the
throw.

[cshapiro1, 2013-11-17 08:03:03]

On Sat, Nov 16, 2013 at 8:38 AM, <rsc@golang.org> wrote:

> No compiler could do that. typeinfoname is not a pure function. It might
> call runtime.throw. Moving it into the if statement would incorrectly
> remove the throw.
>

No, it is possible.  It's a function of the compiler and what it knows (or
doesn't know) about the effects of code being compiled.

What does this have to do with this change?

[rsc, 2013-11-18 21:34:30]

On Sun, Nov 17, 2013 at 3:02 AM, Carl Shapiro <cshapiro@google.com> wrote:

> On Sat, Nov 16, 2013 at 8:38 AM, <rsc@golang.org> wrote:
>
>> No compiler could do that. typeinfoname is not a pure function. It might
>> call runtime.throw. Moving it into the if statement would incorrectly
>> remove the throw.
>>
>
> No, it is possible.
>

I am not talking about whether the optimization of pushing code into a more
control-dependent region is ever possible. I am talking about this specific
line of code that you suggested the compiler could handle differently. I
don't believe it can.


>  It's a function of the compiler and what it knows (or doesn't know) about
> the effects of code being compiled.
>

That statement is true of every compiler optimization ever. In the specific
case of "name = typeinfoname(typ & 3)", the compiler cannot move that
statement inside the if - even though the value of name is only used inside
the if - because it would be moving the possibility of typeinfoname's
runtime.throw call inside the if, removing a possible exit from the
program. A compiler would need not only the necessary logic for the
optimization but also some kind of annotation on typeinfoname to mark it
side-effect-free despite the call to throw.

What does this have to do with this change?
>

Not much. This discussion started because you replied to Dmitriy's comment
in this CL by saying "Good idea, considering the compiler we are using." I
wanted to understand how the compiler we are using is relevant. I don't
believe it is, in this specific case. That is, concretely, if you give gcc
or any other C compiler the source files in this CL, they are not going to
move the entire typeinfoname call inside the if. There are plenty of valid
criticisms of the C compiler, but I don't think this is one.

I'll drop this.

Russ

[dvyukov, 2013-11-19 02:20:24]

On Tue, Nov 19, 2013 at 1:34 AM, Russ Cox <rsc@golang.org> wrote:
> On Sun, Nov 17, 2013 at 3:02 AM, Carl Shapiro <cshapiro@google.com> wrote:
>>
>> On Sat, Nov 16, 2013 at 8:38 AM, <rsc@golang.org> wrote:
>>>
>>> No compiler could do that. typeinfoname is not a pure function. It might
>>> call runtime.throw. Moving it into the if statement would incorrectly
>>> remove the throw.
>>
>>
>> No, it is possible.
>
>
> I am not talking about whether the optimization of pushing code into a more
> control-dependent region is ever possible. I am talking about this specific
> line of code that you suggested the compiler could handle differently. I
> don't believe it can.
>
>>
>>  It's a function of the compiler and what it knows (or doesn't know) about
>> the effects of code being compiled.
>
>
> That statement is true of every compiler optimization ever. In the specific
> case of "name = typeinfoname(typ & 3)", the compiler cannot move that
> statement inside the if - even though the value of name is only used inside
> the if - because it would be moving the possibility of typeinfoname's
> runtime.throw call inside the if, removing a possible exit from the program.
> A compiler would need not only the necessary logic for the optimization but
> also some kind of annotation on typeinfoname to mark it side-effect-free
> despite the call to throw.
>
>> What does this have to do with this change?
>
>
> Not much. This discussion started because you replied to Dmitriy's comment
> in this CL by saying "Good idea, considering the compiler we are using." I
> wanted to understand how the compiler we are using is relevant. I don't
> believe it is, in this specific case. That is, concretely, if you give gcc
> or any other C compiler the source files in this CL, they are not going to
> move the entire typeinfoname call inside the if. There are plenty of valid
> criticisms of the C compiler, but I don't think this is one.
>
> I'll drop this.
>
> Russ


The cost of having few unused statements and an inlinable function
call would be much lower with gcc -O3 (even if it would not move the
code under the if).

[rsc, 2013-11-19 14:42:21]

LGTM

Much clearer, thanks.

https://codereview.appspot.com/21990045/diff/100001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/100001/src/pkg/runtime/mprof.goc...
src/pkg/runtime/mprof.goc:269: uintptr frame;
this isn't a pointer-sized thing. s/uintptr/int32/
and then you can use %d and drop the (uint64) cast in the print

[cshapiro1, 2013-11-19 19:40:54]

https://codereview.appspot.com/21990045/diff/100001/src/pkg/runtime/mprof.goc
File src/pkg/runtime/mprof.goc (right):

https://codereview.appspot.com/21990045/diff/100001/src/pkg/runtime/mprof.goc...
src/pkg/runtime/mprof.goc:269: uintptr frame;
On 2013/11/19 14:42:22, rsc wrote:
> this isn't a pointer-sized thing. s/uintptr/int32/
> and then you can use %d and drop the (uint64) cast in the print

Done.

[cshapiro, 2013-12-03 22:42:43]

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

runtime: add an allocation and free tracing for gc debugging

Output for an allocation and free (sweep) follows

MProf_Malloc(p=0xc2100210a0, size=0x50, type=0x0 <single object>)
        #0 0x46ee15 runtime.mallocgc
/usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:141
        #1 0x47004f runtime.settype_flush
/usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:612
        #2 0x45f92c gc
/usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2071
        #3 0x45f89e mgc
/usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2050
        #4 0x45258b runtime.mcall
/usr/local/google/home/cshapiro/go/src/pkg/runtime/asm_amd64.s:179

MProf_Free(p=0xc2100210a0, size=0x50)
        #0 0x46ee15 runtime.mallocgc
/usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:141
        #1 0x47004f runtime.settype_flush
/usr/local/google/home/cshapiro/go/src/pkg/runtime/malloc.goc:612
        #2 0x45f92c gc
/usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2071
        #3 0x45f89e mgc
/usr/local/google/home/cshapiro/go/src/pkg/runtime/mgc0.c:2050
        #4 0x45258b runtime.mcall
/usr/local/google/home/cshapiro/go/src/pkg/runtime/asm_amd64.s:179

R=golang-dev, dvyukov, rsc, cshapiro
CC=golang-dev
https://codereview.appspot.com/21990045