Skip to content

runtime: occasional crash in concatstring #7083

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
randall77 opened this issue Jan 9, 2014 · 15 comments
Closed

runtime: occasional crash in concatstring #7083

randall77 opened this issue Jan 9, 2014 · 15 comments
Milestone

Comments

@randall77
Copy link
Contributor

Very occasionally builders are failing with a trace something like the ones below.  It
looks like a string that has been freed (its length=second word=0xdeaddead) is still
reachable.

dates:
12/19/2013 darwin/amd64
1/4/2014 darwin/386
1/7/2014 linux/amd64/race
1/8/2014 darwin/386


fatal error: string concatenation too long

goroutine 7 [running]:
runtime.throw(0x5ae0c0)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/runtime/panic.c:462 +0x69 fp=0x119ca58
concatstring(0x119cae0, 0x2, 0x119cac0)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/runtime/string.goc:161 +0x6c fp=0x119caa0
runtime.concatstring2(0x282a40, 0x3, 0x0, 0xdeaddeaddeaddead, 0x281ca0, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/runtime/string.goc:185 +0x28 fp=0x119cac0
go/doc.synopsisFmt(0x0, 0xdeaddeaddeaddead, 0x0, 0x0)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/go/doc/doc_test.go:56 +0x182 fp=0x119cb10
runtime.call32(0x30b8d0, 0xc210137e80)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/runtime/asm_amd64.s:339 +0x32 fp=0x119cb38
reflect.Value.call(0x21ed40, 0x30b8d0, 0x130, 0x283660, 0x4, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/reflect/value.go:506 +0x1734 fp=0x119cf48
----- stack segment boundary -----
reflect.Value.Call(0x21ed40, 0x30b8d0, 0x130, 0xc210137e60, 0x1, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/reflect/value.go:345 +0xab fp=0x119d4e8
text/template.(*state).evalCall(0xc210185e40, 0x1e52e0, 0xc210184790, 0x166, 0x21ed40,
...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:555 +0xaf7 fp=0x119d6e0
text/template.(*state).evalFunction(0xc210185e40, 0x1e52e0, 0xc210184790, 0x166,
0xc21000ac20, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:447 +0x33c fp=0x119d808
text/template.(*state).evalCommand(0xc210185e40, 0x1e52e0, 0xc210184790, 0x166,
0xc2100651e0, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:351 +0x23d fp=0x119d938
text/template.(*state).evalPipeline(0xc210185e40, 0x1e52e0, 0xc210184790, 0x166,
0xc210064370, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:324 +0x1e9 fp=0x119da38
text/template.(*state).walk(0xc210185e40, 0x1e52e0, 0xc210184790, 0x166, 0x6a7378, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:159 +0x17d fp=0x119db78
text/template.(*state).walk(0xc210185e40, 0x1e52e0, 0xc210184790, 0x166, 0x6a8040, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:167 +0x978 fp=0x119dcb8
text/template.func·001(0x1f7700, 0x0, 0x20, 0x1e52e0, 0xc210184790, ...)
        /Users/builder/workspace/darwin-amd64-race-cheney-acad7f360212/go/src/pkg/text/template/exec.go:249 +0x485 fp=0x119ddb0


fatal error: string concatenation too long

goroutine 8 [running]:
runtime.throw(0x381540)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/runtime/panic.c:462 +0x5f fp=0x30716fdc
concatstring(0x30717020, 0x2, 0x30717010)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/runtime/string.goc:161 +0x5b fp=0x30717000
runtime.concatstring2(0x179e58, 0x3, 0x0, 0xdeaddead, 0x179b28, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/runtime/string.goc:185 +0x20 fp=0x30717010
go/doc.synopsisFmt(0x0, 0xdeaddead, 0x0, 0x0)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/go/doc/doc_test.go:56 +0x124 fp=0x30717038
runtime.call16(0x1c8fb8, 0x1072fd40, 0x10)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/runtime/asm_386.s:359 +0x32 fp=0x3071704c
reflect.Value.call(0x142a80, 0x1c8fb8, 0x0, 0x130, 0x17bb48, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/reflect/value.go:614 +0x1038 fp=0x307172e4
reflect.Value.Call(0x142a80, 0x1c8fb8, 0x0, 0x130, 0x1072fd30, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/reflect/value.go:451 +0x75 fp=0x30717318
text/template.(*state).evalCall(0x107391c0, 0x11f120, 0x106c7ec4, 0x0, 0x166, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/text/template/exec.go:555 +0x688 fp=0x3071744c
text/template.(*state).evalFunction(0x107391c0, 0x11f120, 0x106c7ec4, 0x0, 0x166, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/text/template/exec.go:447 +0x1e5 fp=0x307174fc
text/template.(*state).evalCommand(0x107391c0, 0x11f120, 0x106c7ec4, 0x0, 0x166, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/text/template/exec.go:351 +0x139 fp=0x30717584
text/template.(*state).evalPipeline(0x107391c0, 0x11f120, 0x106c7ec4, 0x0, 0x166, ...)
        /Users/builder/workspace/darwin-386-cheney-4a4c92c7a243/go/src/pkg/text/template/exec.go:324 +0xf9 fp=0x30717634
@randall77
Copy link
Contributor Author

Comment 1:

Might be related to issue #7008.

@ianlancetaylor
Copy link
Member

Comment 2:

Labels changed: added release-go1.2.1, repo-main.

Status changed to Accepted.

@randall77
Copy link
Contributor Author

Comment 3:

Why Go 1.2.1?  Is this bug in Go 1.2?  I thought it was just tip.

@ianlancetaylor
Copy link
Member

Comment 4:

As far as I know the bug is only in tip.  But just in case, I marked it 1.2.1, so that
we will consider the fix (if there is one) for the 1.2.1 release (if there is one).  If
there is nothing to fix in 1.2.1, then we can change the tag to Release-Go1.3.

@rsc
Copy link
Contributor

rsc commented Jan 10, 2014

Comment 5:

fwiw
cd $GOROOT/src/pkg/go/doc
go test -c
GOGC=0 ./doc.test -test.run='Test$'
seems to reproduce it reliably for me

@davecheney
Copy link
Contributor

Comment 6:

Using rsc's test I have bisected this to 
changeset:   18730:7e24a86563b4
user:        Keith Randall <khr@golang.org>
date:        Mon Dec 30 12:03:56 2013 -0800
summary:     runtime: use readrange instead of read to check for races
Which is confusing to say the least.
The good news is it does not appear to affect revisions before this, so probably isn't
critical to backport to 1.2.x

@dvyukov
Copy link
Member

dvyukov commented Jan 13, 2014

Comment 7:

I think this is liveness issues:
https://golang.org/issue/7008
Probably stack layout has changed.

@randall77
Copy link
Contributor Author

Comment 8:

Looks like a GC bitmap is wrong.  The function in which this appears is
go/doc.methodSet.set.  The snippet of code is:
    mset[name] = &Func{
        Doc:  f.Doc.Text(),
        Name: name,
        Decl: f,
        Recv: recv,
        Orig: recv,
    }
Here's a hacked-up trace of what is happening:
mallocing 0xc210081b90 doc.Func    <- the &Func{} allocation
mallocing 0xc210081be0/80          <- ? - no type info, probably settype data?
scan go/doc.methodSet.set          <- GC triggered in mapassign
after prologue
full locals info                   <- pointer map for go/doc.methodSet.set
  0x28: 0                          <- bug!
  0x30: 1
  0x38: 0
  0x40: 1
  0x48: 0
  0x50: 1
  0x58: 0
  0x60: 1
  0x68: 0
  0x70: 1
  0x78: 0
full args info
  0x88: 1
  0x90: 1
GC: conservative stack scan        <- all ptr-looking things on the stack that point
to non-marked objects
  ptr not marked testing.RunTests/144 -> 0xc21005d1b0
  ptr not marked go/doc.methodSet.set/40 -> 0xc210081b90  <- this is the bug
  ptr not marked go/doc.test/160 -> 0xc2100c3720
  ptr not marked go/doc.test/168 -> 0xc210053d90
  ptr not marked go/doc.test/200 -> 0xc210053d90
  ptr not marked go/doc.test/208 -> 0xc210051540
  ptr not marked go/doc.test/304 -> 0xc210051540
freeing 0xc210081b90               <- oops!
mallocing 0xc21004b000 map.bucket[string]*doc.Func
Note that a doc.Func is allocated, a GC is run, then that doc.Func is immediately
deallocated.  The bug is the 0x28:0 line.  The return value of the malloc of the Func
structure is stored here.
I haven't delved into the compiler yet, but I suspect this has something to do with
changing the map operations to take pointers instead of values.  The GC that throws away
the doc.Func pointer is called from inside mapassign.  mapassign receives a pointer to
the 0x28 stack slot containing the doc.Func pointer.  The slot is still live because we
have a pointer to it, but maybe the analysis happens before the rewrite to have map ops
take pointers instead of values.  (Before, the doc.Func pointer was copied to the arg
region, so even though the pointer isn't dead, the 0x28 stack slot is.)
The 0x28 slot is otherwise dead after the mapassign.

Status changed to Started.

@randall77
Copy link
Contributor Author

Comment 9:

A simple repro is below.  The pointer map for f is wrong.
package main
func f(m map[int]*string, i int) {
    s := ""
    m[i] = &s
}
func main() {
    m := map[int]*string{}
    for i := 0; i < 40; i++ {
        f(m, i)
        if len(*m[i]) != 0 {
            panic("bad length")
        }
    }
}
go build -gcflags -l bug7083.go
env GOGC=0 ./bug7083
panic: bad length
goroutine 1 [running]:
runtime.panic(0x422ce0, 0xc21000a0a0)
    /usr/local/google/home/khr/sandbox/go-issue7083/src/pkg/runtime/panic.c:264 +0xb6
main.main()
    /usr/local/google/home/khr/go/bug7083.go:13 +0xdf
Note -gcflags -l is not needed, but it isolates the bug in f instead of being part of
main.
If you change f to this, the bug goes away:
func f(m map[int]*string, i int) {
    s := ""
    p := &s
    m[i] = p
}
So it may not have anything to do with maps & passing by pointer.  At least, the
compiler gets that right some of the time.

@davecheney
Copy link
Contributor

Comment 10:

Thanks Keith. I'll try this new test and see if it can detect a change earlier than
7e24a86563b4 which might give a clue, and also indicate if it affects 1.2

@rsc
Copy link
Contributor

rsc commented Jan 14, 2014

Comment 11:

I think I know what's wrong. I found this earlier today while debugging a
crash in html/template that I thought was caused my own changes to the
liveness code. At the time I thought it didn't fix this issue: I reran
go/doc and it still crashed, but it looks like I just didn't recompile
enough code with the fix.
Three CLs on the way:
51010045 cmd/gc: return canonical Node* from temp
51820043 cmd/gc: add -live flag for debugging liveness maps
51830043 runtime: emit collection stacks in GODEBUG=allocfreetrace mode
The first is the bug fix; the others are just help for next time.

@rsc
Copy link
Contributor

rsc commented Jan 14, 2014

Comment 12:

This issue was closed by revision 334056a.

Status changed to Fixed.

@rsc
Copy link
Contributor

rsc commented Feb 14, 2014

Comment 13:

This is marked 1.2.1 but the bug we found was hurting the liveness code, which was not
in 1.2. I am moving it back to 1.3.

Labels changed: added release-go1.3, removed release-go1.2.1.

@gopherbot
Copy link
Contributor

Comment 14:

CL https://golang.org/cl/100800046 mentions this issue.

@rsc
Copy link
Contributor

rsc commented May 28, 2014

Comment 15:

This issue was closed by revision 8a2db40.

@rsc rsc added this to the Go1.3 milestone Apr 14, 2015
@rsc rsc removed the release-go1.3 label Apr 14, 2015
@golang golang locked and limited conversation to collaborators Jun 25, 2016
wheatman pushed a commit to wheatman/go-akaros that referenced this issue Jun 25, 2018
CL 51010045 fixed the first one of these:

        cmd/gc: return canonical Node* from temp

        For historical reasons, temp was returning a copy
        of the created Node*, not the original Node*.
        This meant that if analysis recorded information in the
        returned node (for example, n->addrtaken = 1), the
        analysis would not show up on the original Node*, the
        one kept in fn->dcl and consulted during liveness
        bitmap creation.

        Correct this, and watch for it when setting addrtaken.

        Fixes golang#7083.

        R=khr, dave, minux.ma
        CC=golang-codereviews
        https://golang.org/cl/51010045

CL 53200043 fixed the second:

        cmd/gc: fix race build

        Missed this case in CL 51010045.

        TBR=khr
        CC=golang-codereviews
        https://golang.org/cl/53200043

This CL fixes the third. There are only three nod(OXXX, ...)
calls in sinit.c, so maybe we're done. Embarassing that it
took three CLs to find all three.

Fixes golang#8028.

LGTM=khr
R=golang-codereviews, khr
CC=golang-codereviews, iant
https://golang.org/cl/100800046
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

6 participants