code review 74250043: runtime: fix empty string handling in garbage collector

runtime: fix empty string handling in garbage collector

The garbage collector uses type information to guide the
traversal of the heap. If it sees a field that should be a string,
it marks the object pointed at by the string data pointer as
visited but does not bother to look at the data, because
strings contain bytes, not pointers.

If you save s[len(s):] somewhere, though, the string data pointer
actually points just beyond the string data; if the string data
were exactly the size of an allocated block, the string data
pointer would actually point at the next block. It is incorrect
to mark that next block as visited and not bother to look at
the data, because the next block may be some other type
entirely.

The fix is to ignore strings with zero length during collection:
they are empty and can never become non-empty: the base
pointer will never be used again. The handling of slices already
does this (but using cap instead of len).

This was not a bug in Go 1.2, because until January all string
allocations included a trailing NUL byte not included in the
length, so s[len(s):] still pointed inside the string allocation
(at the NUL).

This bug was causing the crashes in test/run.go. Specifically,
the parsing of a regexp in package regexp/syntax allocated a
[]syntax.Inst with rounded size 1152 bytes. In fact it
allocated many such slices, because during the processing of
test/index2.go it creates thousands of regexps that are all
approximately the same complexity. That takes a long time, and
test/run works on other tests in other goroutines. One such
other test is chan/perm.go, which uses an 1152-byte source
file. test/run reads that file into a []byte and then calls
strings.Split(string(src), "\n"). The string(src) creates an
1152-byte string - and there's a very good chance of it
landing next to one of the many many regexp slices already
allocated - and then because the file ends in a \n,
strings.Split records the tail empty string as the final
element in the slice. A garbage collection happens at this
point, the collection finds that string before encountering
the []syntax.Inst data it now inadvertently points to, and the
[]syntax.Inst data is not scanned for the pointers that it
contains. Each syntax.Inst contains a []rune, those are
missed, and the backing rune arrays are freed for reuse. When
the regexp is later executed, the runes being searched for are
no longer runes at all, and there is no match, even on text
that should match.

On 64-bit machines the pointer in the []rune inside the
syntax.Inst is larger (along with a few other pointers),
pushing the []syntax.Inst backing array into a larger size
class, avoiding the collision with chan/perm.go's
inadvertently sized file.

I expect this was more prevalent on OS X than on Linux or
Windows because those managed to run faster or slower and
didn't overlap index2.go with chan/perm.go as often. On the
ARM systems, we only run one errorcheck test at a time, so
index2 and chan/perm would never overlap.

It is possible that this bug is the root cause of other crashes
as well. For now we only know it is the cause of the test/run crash.

Many thanks to Dmitriy for help debugging.

Fixes issue 7344.
Fixes issue 7455.

[rsc, 2014-03-12 02:47:32]

Hello golang-codereviews@googlegroups.com (cc: dvyukov, iant, khr, r),

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

[dave_cheney.net, 2014-03-12 02:53:58]

Excellent find Russ. I wonder if this is the cause of the random
reports from some linux users that ./all.bash crashes during their
builds.

On Wed, Mar 12, 2014 at 1:47 PM,  <rsc@golang.org> wrote:
> Reviewers: golang-codereviews,
>
> Message:
> Hello golang-codereviews@googlegroups.com (cc: dvyukov, iant, khr, r),
>
> I'd like you to review this change to
> https://code.google.com/p/go/
>
>
> Description:
> runtime: fix empty string handling in garbage collector
>
> The garbage collector uses type information to guide the
> traversal of the heap. If it sees a field that should be a string,
> it marks the object pointed at by the string data pointer as
> visited but does not bother to look at the data, because
> strings contain bytes, not pointers.
>
> If you save s[len(s):] somewhere, though, the string data pointer
> actually points just beyond the string data; if the string data
> were exactly the size of an allocated block, the string data
> pointer would actually point at the next block. It is incorrect
> to mark that next block as visited and not bother to look at
> the data, because the next block may be some other type
> entirely.
>
> The fix is to ignore strings with zero length during collection:
> they are empty and can never become non-empty: the base
> pointer will never be used again. The handling of slices already
> does this (but using cap instead of len).
>
> This was not a bug in Go 1.2, because until January all string
> allocations included a trailing NUL byte not included in the
> length, so s[len(s):] still pointed inside the string allocation
> (at the NUL).
>
> This bug was causing the crashes in test/run.go. Specifically,
> the parsing of a regexp in package regexp/syntax allocated a
> []syntax.Inst with rounded size 1152 bytes. In fact it
> allocated many such slices, because during the processing of
> test/index2.go it creates thousands of regexps that are all
> approximately the same complexity. That takes a long time, and
> test/run works on other tests in other goroutines. One such
> other test is chan/perm.go, which uses an 1152-byte source
> file. test/run reads that file into a []byte and then calls
> strings.Split(string(src), "\n"). The string(src) creates an
> 1152-byte string - and there's a very good chance of it
> landing next to one of the many many regexp slices already
> allocated - and then because the file ends in a \n,
> strings.Split records the tail empty string as the final
> element in the slice. A garbage collection happens at this
> point, the collection finds that string before encountering
> the []syntax.Inst data it now inadvertently points to, and the
> []syntax.Inst data is not scanned for the pointers that it
> contains. Each syntax.Inst contains a []rune, those are
> missed, and the backing rune arrays are freed for reuse. When
> the regexp is later executed, the runes being searched for are
> no longer runes at all, and there is no match, even on text
> that should match.
>
> On 64-bit machines the pointer in the []rune inside the
> syntax.Inst is larger (along with a few other pointers),
> pushing the []syntax.Inst backing array into a larger size
> class, avoiding the collision with chan/perm.go's
> inadvertently sized file.
>
> I expect this was more prevalent on OS X than on Linux or
> Windows because those managed to run faster or slower and
> didn't overlap index2.go with chan/perm.go as often. On the
> ARM systems, we only run one errorcheck test at a time, so
> index2 and chan/perm would never overlap.
>
> It is possible that this bug is the root cause of other crashes
> as well. For now we only know it is the cause of the test/run crash.
>
> Many thanks to Dmitriy for help debugging.
>
> Fixes issue 7344.
>
> Please review this at https://codereview.appspot.com/74250043/
>
> Affected files (+49, -2 lines):
>   M src/pkg/runtime/mgc0.c
>   A test/gcstring.go
>
>
> Index: src/pkg/runtime/mgc0.c
> ===================================================================
> --- a/src/pkg/runtime/mgc0.c
> +++ b/src/pkg/runtime/mgc0.c
> @@ -781,6 +781,7 @@
>         void *obj;
>         Type *t;
>         Slice *sliceptr;
> +       String *stringptr;
>         Frame *stack_ptr, stack_top, stack[GC_STACK_CAPACITY+4];
>         BufferList *scanbuffers;
>         Scanbuf sbuf;
> @@ -951,8 +952,11 @@
>                         break;
>
>                 case GC_STRING:
> -                       obj = *(void**)(stack_top.b + pc[1]);
> -                       markonly(obj);
> +                       stringptr = (String*)(stack_top.b + pc[1]);
> +                       if(stringptr->len != 0) {
> +                               obj = stringptr->str;
> +                               markonly(obj);
> +                       }
>                         pc += 2;
>                         continue;
>
> Index: test/gcstring.go
> ===================================================================
> new file mode 100644
> --- /dev/null
> +++ b/test/gcstring.go
> @@ -0,0 +1,43 @@
> +// Copyright 2014 The Go Authors.  All rights reserved.
> +// Use of this source code is governed by a BSD-style
> +// license that can be found in the LICENSE file.
> +
> +package main
> +
> +import (
> +       "runtime"
> +       "time"
> +)
> +
> +type T struct {
> +       ptr **int
> +       pad [120]byte
> +}
> +
> +var things []interface{}
> +
> +func main() {
> +       setup()
> +       runtime.GC()
> +       runtime.GC()
> +       time.Sleep(10*time.Millisecond)
> +       runtime.GC()
> +       runtime.GC()
> +       time.Sleep(10*time.Millisecond)
> +}
> +
> +func setup() {
> +       var Ts []interface{}
> +       buf := make([]byte, 128)
> +
> +       for i := 0; i < 10000; i++ {
> +               s := string(buf)
> +               t := &T{ptr: new(*int)}
> +               runtime.SetFinalizer(t.ptr, func(**int) { panic("*int freed
> too early") })
> +               Ts = append(Ts, t)
> +               things = append(things, s[len(s):])
> +       }
> +
> +       things = append(things, Ts...)
> +}
> +
>
>
> --
> 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/d/optout.

[rsc, 2014-03-12 02:55:41]

It's possible but only at tip and only since January 27.

Russ

[r, 2014-03-12 03:35:22]

LGTM but please explain purpose of test in test code.

https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go
File test/gcstring.go (right):

https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go#newcode3
test/gcstring.go:3: // license that can be found in the LICENSE file.

// Verify that an empty slice created at the end of a string points to the
original string rather than the following object.

[dave_cheney.net, 2014-03-12 03:35:44]

I'm seeing this odd error,

odessa(~/go/test) % go run run.go

# go run run.go -- gcstring.go

unexpected skip for gcstring.go:

FAIL gcstring.go 0.000s

On Wed, Mar 12, 2014 at 2:35 PM,  <r@golang.org> wrote:
> LGTM but please explain purpose of test in test code.
>
>
> https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go
> File test/gcstring.go (right):
>
> https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go#newcode3
> test/gcstring.go:3: // license that can be found in the LICENSE file.
>
> // Verify that an empty slice created at the end of a string points to
> the original string rather than the following object.
>
> https://codereview.appspot.com/74250043/

[rsc, 2014-03-12 03:38:44]

On Tue, Mar 11, 2014 at 11:35 PM, Dave Cheney <dave@cheney.net> wrote:

> I'm seeing this odd error,
>
> odessa(~/go/test) % go run run.go
>
> # go run run.go -- gcstring.go
>
> unexpected skip for gcstring.go:
>

thanks. that means i forgot the test header.

[dvyukov, 2014-03-12 03:40:50]

LGTM
striking story!

[jasdel, 2014-03-12 03:47:07]

On 2014/03/12 03:35:44, dfc wrote:
> I'm seeing this odd error,
> 
> odessa(~/go/test) % go run run.go
> 
> # go run run.go -- gcstring.go
> 
> unexpected skip for gcstring.go:
> 
> FAIL gcstring.go 0.000s
> 
> On Wed, Mar 12, 2014 at 2:35 PM,  <mailto:r@golang.org> wrote:
> > LGTM but please explain purpose of test in test code.
> >
> >
> > https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go
> > File test/gcstring.go (right):
> >
> > https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go#newcode3
> > test/gcstring.go:3: // license that can be found in the LICENSE file.
> >
> > // Verify that an empty slice created at the end of a string points to
> > the original string rather than the following object.
> >
> > https://codereview.appspot.com/74250043/

This patch fixes all.bash ending with a panic while compiling runtime/cgo on
Ubuntu 13.10 x86_64. Though having the same issue as dfc where the
test/gcstrings.go is unexpectedly skipped.

[rsc, 2014-03-12 03:48:47]

On Tue, Mar 11, 2014 at 11:47 PM, <delpontej@gmail.com> wrote:

> This patch fixes all.bash ending with a panic while compiling
> runtime/cgo on Ubuntu 13.10 x86_64.
>

Great, thank you.  Is there an issue filed for that?

Russ

[dave_cheney.net, 2014-03-12 03:49:09]

LGTM.

Fixes issue 7455.

[iant, 2014-03-12 03:57:56]

LGTM

https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go
File test/gcstring.go (right):

https://codereview.appspot.com/74250043/diff/60001/test/gcstring.go#newcode1
test/gcstring.go:1: // Copyright 2014 The Go Authors.  All rights reserved.
File should start with 

// run

[rsc, 2014-03-12 03:58:57]

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

runtime: fix empty string handling in garbage collector

The garbage collector uses type information to guide the
traversal of the heap. If it sees a field that should be a string,
it marks the object pointed at by the string data pointer as
visited but does not bother to look at the data, because
strings contain bytes, not pointers.

If you save s[len(s):] somewhere, though, the string data pointer
actually points just beyond the string data; if the string data
were exactly the size of an allocated block, the string data
pointer would actually point at the next block. It is incorrect
to mark that next block as visited and not bother to look at
the data, because the next block may be some other type
entirely.

The fix is to ignore strings with zero length during collection:
they are empty and can never become non-empty: the base
pointer will never be used again. The handling of slices already
does this (but using cap instead of len).

This was not a bug in Go 1.2, because until January all string
allocations included a trailing NUL byte not included in the
length, so s[len(s):] still pointed inside the string allocation
(at the NUL).

This bug was causing the crashes in test/run.go. Specifically,
the parsing of a regexp in package regexp/syntax allocated a
[]syntax.Inst with rounded size 1152 bytes. In fact it
allocated many such slices, because during the processing of
test/index2.go it creates thousands of regexps that are all
approximately the same complexity. That takes a long time, and
test/run works on other tests in other goroutines. One such
other test is chan/perm.go, which uses an 1152-byte source
file. test/run reads that file into a []byte and then calls
strings.Split(string(src), "\n"). The string(src) creates an
1152-byte string - and there's a very good chance of it
landing next to one of the many many regexp slices already
allocated - and then because the file ends in a \n,
strings.Split records the tail empty string as the final
element in the slice. A garbage collection happens at this
point, the collection finds that string before encountering
the []syntax.Inst data it now inadvertently points to, and the
[]syntax.Inst data is not scanned for the pointers that it
contains. Each syntax.Inst contains a []rune, those are
missed, and the backing rune arrays are freed for reuse. When
the regexp is later executed, the runes being searched for are
no longer runes at all, and there is no match, even on text
that should match.

On 64-bit machines the pointer in the []rune inside the
syntax.Inst is larger (along with a few other pointers),
pushing the []syntax.Inst backing array into a larger size
class, avoiding the collision with chan/perm.go's
inadvertently sized file.

I expect this was more prevalent on OS X than on Linux or
Windows because those managed to run faster or slower and
didn't overlap index2.go with chan/perm.go as often. On the
ARM systems, we only run one errorcheck test at a time, so
index2 and chan/perm would never overlap.

It is possible that this bug is the root cause of other crashes
as well. For now we only know it is the cause of the test/run crash.

Many thanks to Dmitriy for help debugging.

Fixes issue 7344.
Fixes issue 7455.

LGTM=r, dvyukov, dave, iant
R=golang-codereviews, dave, r, dvyukov, delpontej, iant
CC=golang-codereviews, khr
https://codereview.appspot.com/74250043

[josharian, 2014-03-12 23:42:13]

Awesome. Thanks for the thorough explanation.

For future reference -- since I also poked at this but got nowhere -- what were
the primary tools you used in tracking this down?

-josh

[rsc, 2014-03-13 01:15:58]

On Wed, Mar 12, 2014 at 7:42 PM, <josharian@gmail.com> wrote:

> Awesome. Thanks for the thorough explanation.
>
> For future reference -- since I also poked at this but got nowhere --
> what were the primary tools you used in tracking this down?
>

i don't feel like i got that far either honestly.

first i tried dumping the goroutine stacks at every garbage collection, and
i ran a few thousand instances of run.go with that turned on. i made a list
for each run of all the function pc's seen and i tried to find function
pc's that only appeared in failing runs or that were strongly indicative of
a failing run. that would suggest a place where the liveness bitmaps might
be wrong. that was a dead end.

i made the run.go program compile and save two of each regexp and panic
when they disagreed. that gave me a foothold; next was to sleep when they
disagreed so i could attach gdb and look around. using gdb to dump memory
(on a mac so gdb barely works) i found that it was always the rune slice
that had been reused incorrectly. that let me write a Check method on
regexp.Regexp that called Check on Prog that checked that the rune slice
contained actual runes (0...10ffff). if not it panicked. i inserted Check
calls in various places but the one that helped the most turned out to be
in the for _, we := range loop in run.go. maybe another loop just to do
Check after that loop finished would have helped too. at that point i knew
what to look for, and Check could print the address of the reused slice
data.

then i was able to reproduce it using GODEBUG=allocfreetrace=1. the most
interesting bit from that was that you could see the pointer being
allocated and then surviving at least a few garbage collections before
being freed incorrectly. surviving the first garbage collection strongly
suggested it was not a bug in the liveness analysis, because those bugs
matter only until the pointer is linked into the main heap object graph. in
fact the one i looked at most carefully survived 17 garbage collections
before dying mysteriously.

at this point i asked dmitriy about background sweep, because i could see
that the free was happening due to an on-demand sweep during an ordinary
allocation. i described what i knew and he didn't have any useful ideas at
the time. but then before he went to bed he pinged me to say 'maybe
s[len(s):] is mishandled now that there are no terminating NULs.' the data
i'd collected confirmed that this could be the problem and provided the
details needed to explain the specific failure patterns we were seeing.

so really i just flailed around for a few days until dmitriy had the right
insight (to be fair, he removed the terminating NUL too). but my flailing
produced data that backed up the insight.

russ