code review 7093045: runtime: try to determine the actual type during garbag...

runtime: try to determine the actual type during garbage collection

If the scanned block has no typeinfo the garbage collector will attempt
to get the actual type of the block.

[atom, 2013-01-11 15:41:50]

Hello golang-dev@googlegroups.com,

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

[atom, 2013-01-15 17:57:36]

On 2013/01/11 15:41:50, atom wrote:
> Hello mailto:golang-dev@googlegroups.com,
> 
> I'd like you to review this change to
> https://go.googlecode.com/hg/

I would like to obtain information about the progress of this codereview.
Thanks.

[bradfitz, 2013-01-15 18:19:29]

On Tue, Jan 15, 2013 at 9:57 AM, <0xE2.0x9A.0x9B@gmail.com> wrote:

> On 2013/01/11 15:41:50, atom wrote:
>
>> Hello mailto:golang-dev@**googlegroups.com <golang-dev@googlegroups.com>,
>>
>
>  I'd like you to review this change to
>> https://go.googlecode.com/hg/
>>
>
> I would like to obtain information about the progress of this
> codereview. Thanks.
>

A shorter way to say that is "ping".

Russ is just recently back (see his recent "not reading code" email).

[rsc, 2013-01-18 21:39:11]

LGTM

[rsc, 2013-01-18 21:40:52]

Please hg sync + hg mail again. It looks like something changed in mgc0.c.

[atom, 2013-01-18 21:50:10]

Hello golang-dev@googlegroups.com, bradfitz@golang.org, rsc@golang.org (cc:
golang-dev@googlegroups.com),

Please take another look.

[rsc, 2013-01-18 21:56:21]

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

runtime: try to determine the actual type during garbage collection

If the scanned block has no typeinfo the garbage collector will attempt
to get the actual type of the block.

R=golang-dev, bradfitz, rsc
CC=golang-dev
https://codereview.appspot.com/7093045

Committer: Russ Cox <rsc@golang.org>

[rsc, 2013-01-29 17:33:00]

I am trying to use tip with some large programs and I am finding that this CL
causes the os.Args slice - one of the earliest allocations in the program - to
be reclaimed prematurely. I have not been able to cut the test case to something
manageable yet, but bypassing the type detection with
https://codereview.appspot.com/7245043 fixes the problem.

Any ideas?

Russ

[iant2, 2013-01-29 18:00:32]

On Tue, Jan 29, 2013 at 9:33 AM,  <rsc@golang.org> wrote:
> I am trying to use tip with some large programs and I am finding that
> this CL causes the os.Args slice - one of the earliest allocations in
> the program - to be reclaimed prematurely. I have not been able to cut
> the test case to something manageable yet, but bypassing the type
> detection with https://codereview.appspot.com/7245043 fixes the problem.

ITYM https://codereview.appspot.com/7226055/ .

Ian

[atom, 2013-01-29 18:58:05]

On 2013/01/29 17:33:00, rsc wrote:
> I am trying to use tip with some large programs and I am finding that this CL
> causes the os.Args slice - one of the earliest allocations in the program - to
> be reclaimed prematurely. I have not been able to cut the test case to
something
> manageable yet, but bypassing the type detection with
> https://codereview.appspot.com/7245043 fixes the problem.
> 
> Any ideas?
> 
> Russ

Is the program making use of the reflect package?

Does the premature reclamation happen when the program is starting, or later?

[rsc, 2013-01-29 21:13:35]

On Tue, Jan 29, 2013 at 10:58 AM, <0xE2.0x9A.0x9B@gmail.com> wrote:

> On 2013/01/29 17:33:00, rsc wrote:
>
>> I am trying to use tip with some large programs and I am finding that
>>
> this CL
>
>> causes the os.Args slice - one of the earliest allocations in the
>>
> program - to
>
>> be reclaimed prematurely. I have not been able to cut the test case to
>>
> something
>
>> manageable yet, but bypassing the type detection with
>>
https://codereview.appspot.**com/7245043<https://codereview.appspot.com/72450...
the problem.
>>
>
>  Any ideas?
>>
>
>  Russ
>>
>
> Is the program making use of the reflect package?
>

I don't believe so.


> Does the premature reclamation happen when the program is starting, or
> later?
>

It seems to happen very early, by the time func main has started. The
memory used by os.Args appears to be reused for a MSpan header.

Russ

[atom, 2013-01-30 17:48:08]

On 2013/01/29 21:13:35, rsc wrote:
> It seems to happen very early, by the time func main has started. The
> memory used by os.Args appears to be reused for a MSpan header.

Do you mean the following allocation:

http://code.google.com/p/go/source/browse/src/pkg/runtime/runtime.c?r=640397f...

It appears I am unable to figure out the cause of the issue without a test case.

[rsc, 2013-01-30 17:56:19]

Yes, that's the allocation. I am going to try to winnow the example down to
a decent test case later today.

Russ

[rsc, 2013-01-30 23:57:02]

This reproduces the crash on both Linux and OS X amd64, building at tip.

$ cat main.go
package main

import (
"os"
_ "./p"
)

func main() {
os.Stat(os.Args[0])
}
$ cat p/p.go
package p

import "os"

func unused() {
for arg := os.Args[1:]; len(arg) > 0; {
}
}
$ go run main.go
unexpected fault address 0x5002200001
fatal error: fault
[signal 0xb code=0x1 addr=0x5002200001 pc=0x41c105]

goroutine 1 [running]:
runtime.throw(0x4881ca, 0x5002200001)
/home/rsc/go/src/pkg/runtime/panic.c:462 +0x67
runtime.sigpanic()
/home/rsc/go/src/pkg/runtime/thread_linux.c:202 +0xe7
syscall.ByteSliceFromString(0x5002200001, 0xc200018078, 0xc200046000,
0xc2000290c0, 0x419960, ...)
/home/rsc/go/src/pkg/syscall/syscall.go:38 +0x45
syscall.BytePtrFromString(0x5002200001, 0xc200018078, 0x100000001,
0x2cc00000001, 0x4464e0, ...)
/home/rsc/go/src/pkg/syscall/syscall.go:56 +0x2f
syscall.Stat(0x5002200001, 0xc200018078, 0xc200046000, 0x0, 0x0, ...)
/home/rsc/go/src/pkg/syscall/zerrors_linux_amd64.go:3179 +0x44
os.Stat(0x5002200001, 0xc200018078, 0x0, 0x0, 0x0, ...)
/home/rsc/go/src/pkg/os/file_unix.go:132 +0x6f
main.main()
/home/rsc/main.go:9 +0x3d
runtime.main()
/home/rsc/go/src/pkg/runtime/proc.c:257 +0x99
runtime.goexit()
/home/rsc/go/src/pkg/runtime/proc.c:286
exit status 2
$

Using hardware watchpoints I can see the memory get collected:

$ go build main.go
$ gdb main
Reading symbols from /home/rsc/main...done.
Loading Go Runtime support.
(gdb) print &'os.Args'
$1 = (uintptr *) 0x48aaf8 <os.Args>
(gdb) watch *(uintptr*)0x48aaf8
Hardware watchpoint 1: *(uintptr*)0x48aaf8
(gdb) r
Starting program: /home/rsc/main
goenvs_args 1 0x7fffffffe808 0x7fffffffead2 0x0
Hardware watchpoint 1: *(uintptr*)0x48aaf8

Old value = 0
New value = 833223753728
# NOTE: gdb is showing the line *after* the instruction that did the write.
runtime.goargs () at /home/rsc/go/src/pkg/runtime/runtime.c:93
93 os·Args.len = argc;
(gdb) print/x *(uintptr*)0x48aaf8
$3 = 0xc200018000
(gdb) watch *(uintptr*)0xc200018000
Hardware watchpoint 2: *(uintptr*)0xc200018000
(gdb) x/2xg 0xc200018000
0xc200018000: 0x00007fffffffead2 0x000000000000000e
(gdb) c
Continuing.
goenvs_unix 1 0x7fffffffeae1
Hardware watchpoint 2: *(uintptr*)0xc200018000

Old value = 140737488349906
New value = 833223754240
# NOTE: gdb is showing the line *after* again. The actual line is:
158 end->next = s->freelist;
runtime.MCentral_FreeSpan (c=void, s=void, n=void, start=void, end=void)
    at /home/rsc/go/src/pkg/runtime/mcentral.c:159
159 s->freelist = start;
(gdb) where
#0  runtime.MCentral_FreeSpan (c=void, s=void, n=void, start=void, end=void)
    at /home/rsc/go/src/pkg/runtime/mcentral.c:159
#1  0x00000000004095fc in sweepspan (idx=void)
    at /home/rsc/go/src/pkg/runtime/mgc0.c:1256
#2  0x000000000040d034 in runtime.parfordo (desc=void)
    at /home/rsc/go/src/pkg/runtime/parfor.c:101
#3  0x0000000000409f27 in gc (args=void)
    at /home/rsc/go/src/pkg/runtime/mgc0.c:1539
#4  0x00000000004177a0 in ?? ()
    at /home/rsc/go/src/pkg/runtime/asm_amd64.s:242
#5  0x00007ffff7f7edb4 in ?? ()
#6  0x00007ffff7f7e100 in ?? ()
#7  0x00007ffff7f7efb8 in ?? ()
#8  0x00007ffff7f7ed80 in ?? ()
#9  0x0000000000409beb in runtime.gc (force=void)
    at /home/rsc/go/src/pkg/runtime/mgc0.c:1462
#10 0x0000000000000000 in ?? ()
(gdb)

[atom, 2013-01-31 08:28:19]

On 2013/01/30 23:57:02, rsc wrote:
> This reproduces the crash on both Linux and OS X amd64, building at tip.
> 
> $ cat main.go
> package main
> ...

I am unable to reproduce the failure on linux/amd64. go version devel
+9ff35ff05de6

$ GOGCTRACE=1 ./main
gc1(1): 0+0+0 ms, 0 -> 0 MB 17 -> 19 (20-1) objects, 0(0) handoff, 0(0) steal,
0/0/0 yields

[rsc, 2013-01-31 15:32:43]

I'm not sure what's different. I'll send you a Linux binary.

[atom, 2013-01-31 17:16:13]

On 2013/01/31 15:32:43, rsc wrote:
> I'm not sure what's different. I'll send you a Linux binary.

It appears that os.Args has a wrong type: uintptr.

GDB prints:

  (gdb) print &'os.Args'
  $1 = (uintptr *) 0x48aad0

but it should print something like:

  (gdb) print &'os.Args'
  $1 =  []string *

or (no imports, empty func main()):

  (gdb) print &'os.Args'
  $1 = (<data variable, no debug info> *) 0x807b118 <os.Args>  


There are two debugging print statements in ld/data.c:gcaddsym
(http://code.google.com/p/go/source/browse/src/cmd/ld/data.c?r=1eadf11dd1b7b19...).

Uncommenting the two print statements and running 'go build' on your machine
should yield:

$ go build main.go | grep os.Args
gcaddsym:    os.Args    12    type.[]string

[rsc, 2013-01-31 17:23:17]

You're right, it says os.Args 24 type.uintptr. I wonder why.

Russ

[iant2, 2013-01-31 17:46:14]

On Thu, Jan 31, 2013 at 9:23 AM, Russ Cox <rsc@golang.org> wrote:
> You're right, it says os.Args 24 type.uintptr. I wonder why.

Presumably because when you compile the runtime package there is
nothing anywhere to say what the type of os.Args should be.  The type
of os.Args is given in the os package, not the runtime package.

Ian

[rsc, 2013-02-25 15:12:57]

Moved to the issue tracker (issue 4907).