Skip to content
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

runtime: SIGILL in runtime.mapiternext on amd64 with 1.6rc2 #14306

Closed
tsuna opened this issue Feb 12, 2016 · 18 comments
Closed

runtime: SIGILL in runtime.mapiternext on amd64 with 1.6rc2 #14306

tsuna opened this issue Feb 12, 2016 · 18 comments
Milestone

Comments

@tsuna
Copy link
Contributor

tsuna commented Feb 12, 2016

What version of Go are you using (go version)?
go version go1.6rc2 darwin/amd64
What operating system and processor architecture are you using?

Mac OS X 10.9.5 on Intel Core i7-3615QM

What did you do?
go test ./key -run notest -bench .

in the package github.com/aristanetworks/goarista checked out at revision tsuna/goarista@d53bff3

What did you expect to see?

Benchmarks should pass.

What did you see instead?

I've seen this once:

SIGILL: illegal instruction
PC=0xa939 m=2

goroutine 11 [running]:
runtime.mapiternext(0x820306120)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:718 +0x279 fp=0x8203b46e0 sp=0x8203b4650
runtime.mapiterinit(0x147820, 0x820708000, 0x820306120)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:666 +0x2af fp=0x8203b4710 sp=0x8203b46e0
reflect.mapiterinit(0x147820, 0x820708000, 0x15)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:1014 +0x4a fp=0x8203b4738 sp=0x8203b4710
reflect.Value.MapKeys(0x147820, 0x820708000, 0x15, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/reflect/value.go:1075 +0xec fp=0x8203b47f8 sp=0x8203b4738
fmt.(*pp).printReflectValue(0x82034a1a0, 0x147820, 0x820708000, 0x15, 0x76, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:893 +0x2500 fp=0x8203b4fb0 sp=0x8203b47f8
fmt.(*pp).printArg(0x82034a1a0, 0x147820, 0x820708000, 0x76, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:810 +0x540 fp=0x8203b5138 sp=0x8203b4fb0
fmt.(*pp).doPrintf(0x82034a1a0, 0x1bdf90, 0xc, 0x8203b5568, 0x1, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:1238 +0x1dcd fp=0x8203b54c0 sp=0x8203b5138
fmt.Sprintf(0x1bdf90, 0xc, 0x8203b5568, 0x1, 0x1, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:203 +0x6f fp=0x8203b5510 sp=0x8203b54c0
github.com/aristanetworks/goarista/key.keyImpl.GoString(0x1380e0, 0x820712000, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/key/key.go:134 +0x110 fp=0x8203b55a8 sp=0x8203b5510
github.com/aristanetworks/goarista/key.(*keyImpl).GoString(0x820580010, 0x0, 0x0)
    <autogenerated>:8 +0xa4 fp=0x8203b55e0 sp=0x8203b55a8
fmt.(*pp).handleMethods(0x82034a0d0, 0x800000076, 0x0, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:707 +0x32e fp=0x8203b56c0 sp=0x8203b55e0
fmt.(*pp).printArg(0x82034a0d0, 0x1a2e40, 0x820580010, 0x76, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:806 +0x4a9 fp=0x8203b5848 sp=0x8203b56c0
fmt.(*pp).doPrintf(0x82034a0d0, 0x1bb9a0, 0x8, 0x8203b5d90, 0x1, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:1238 +0x1dcd fp=0x8203b5bd0 sp=0x8203b5848
fmt.Sprintf(0x1bb9a0, 0x8, 0x8203b5d90, 0x1, 0x1, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:203 +0x6f fp=0x8203b5c20 sp=0x8203b5bd0
testing.(*common).Fatalf(0x82038a000, 0x1bb9a0, 0x8, 0x8203b5d90, 0x1, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:388 +0x49 fp=0x8203b5c70 sp=0x8203b5c20
github.com/aristanetworks/goarista/key_test.BenchmarkGetFromMapWithMapKey(0x82038a000)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/key/key_test.go:500 +0x2275 fp=0x8203b5f20 sp=0x8203b5c70
testing.(*B).runN(0x82038a000, 0xf4240)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:135 +0x9a fp=0x8203b5f40 sp=0x8203b5f20
testing.(*B).launch(0x82038a000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:227 +0x131 fp=0x8203b5f98 sp=0x8203b5f40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x8203b5fa0 sp=0x8203b5f98
created by testing.(*B).run
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:190 +0x54

goroutine 1 [chan receive]:
testing.(*B).run(0x82038a000, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:191 +0x7b
testing.RunBenchmarks(0x204b50, 0x29aa40, 0x3, 0x3)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:343 +0x76c
testing.(*M).Run(0x82032fef8, 0xffffffffffffffff)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:524 +0x1c9
main.main()
    github.com/aristanetworks/goarista/key/_test/_testmain.go:74 +0x117

rax    0xbeaee92d5ea30650
rbx    0xbeaee92d5ea306d8
rcx    0x8202f1080
rdx    0x0
rdi    0x203d40
rsi    0x147820
rbp    0xbeaee92d5ea30650
rsp    0x8203b4650
r8     0x0
r9     0x0
r10    0xbeaee92d5ea30658
r11    0x0
r12    0x8
r13    0x203d3f
r14    0xf
r15    0x8
rip    0xa939
rflags 0x10293
cs     0x2b
fs     0x0
gs     0x0

The benchmark is very simple and doesn't involve any concurrency.

I recently switched to 1.6rc2 for my dev env on my laptop, and I've seen another crash with a similar signature in another more complicated test that involves non-open source code. I blamed the crash on a potential race condition to track down and made a note for later. But now that this crash happened on a very simple test case in a very small and self-contained library that is open-source, I feel compelled to open a bug to have this investigated.

The other crash I've seen was (there are 2 stack frames I "anonymized", the other ones involve open-source code too):

SIGILL: illegal instruction
PC=0xbaa9 m=9
goroutine 60 [running]:
runtime.mapiternext(0xc820294360)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:718 +0x279 fp=0xc820304af8 sp=0xc820304a68
runtime.mapiterinit(0x505120, 0xc8201fa750, 0xc820294360)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:666 +0x2af fp=0xc820304b28 sp=0xc820304af8
reflect.mapiterinit(0x505120, 0xc8201fa750, 0x1b5)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:1014 +0x4a fp=0xc820304b50 sp=0xc820304b28
reflect.Value.MapKeys(0x505120, 0xc820500030, 0x1b5, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/reflect/value.go:1075 +0xec fp=0xc820304c10 sp=0xc820304b50
github.com/aristanetworks/goarista/test.prettyPrintWithType(0x505120, 0xc820500030, 0x1b5, 0xc8204c4ed0, 0x5, 0x101, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:71 +0x1c72 fp=0xc8203050b0 sp=0xc820304c10
github.com/aristanetworks/goarista/test.prettyPrintWithType(0x4e3880, 0xc820500030, 0x36, 0xc8204c4ed0, 0x6, 0x1, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:63 +0x2732 fp=0xc820305550 sp=0xc8203050b0
github.com/aristanetworks/goarista/test.prettyPrintWithType(0x5012e0, 0xc8201f22b0, 0xb4, 0xc8204c4ed0, 0x7, 0x1, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:65 +0x1a2d fp=0xc8203059f0 sp=0xc820305550
github.com/aristanetworks/goarista/test.prettyPrint(0x5012e0, 0xc8201f22b0, 0xb4, 0xc8204c4ed0, 0x7, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:38 +0x5a fp=0xc820305a38 sp=0xc8203059f0
github.com/aristanetworks/goarista/test.prettyPrintWithType(0x63cce0, 0xc8201f22b0, 0x99, 0xc8204c4ed0, 0x8, 0x1, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:108 +0x3118 fp=0xc820305ed8 sp=0xc820305a38
github.com/aristanetworks/goarista/test.prettyPrint(0x63cce0, 0xc8201f22b0, 0x99, 0xc8204c4ed0, 0x8, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:38 +0x5a fp=0xc820305f20 sp=0xc820305ed8
github.com/aristanetworks/goarista/test.PrettyPrintWithDepth(0x63cce0, 0xc8201f22b0, 0x8, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:23 +0xba fp=0xc820305f78 sp=0xc820305f20
github.com/aristanetworks/goarista/test.PrettyPrint(0x63cce0, 0xc8201f22b0, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/test/pretty.go:17 +0x43 fp=0xc820305fa8 sp=0xc820305f78
arista/xxx.yyy(0x1888db0, 0xc8204e89a0, 0xc8201df880, 0xc820317170)
    /Users/tsuna/go/src/arista/xxx/foo.go:4744 +0xffa fp=0xc820306228 sp=0xc820305fa8
arista/xxx.zzz(0xc82009a240)
    /Users/tsuna/go/src/arista/xxx/foo.go:4564 +0x77d95 fp=0xc820319f18 sp=0xc820306228
testing.tRunner(0xc82009a240, 0xdf5e10)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:473 +0x98 fp=0xc820319f50 sp=0xc820319f18
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820319f58 sp=0xc820319f50
created by testing.RunTests
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:582 +0x892

In 6 days of using Go 1.6rc2 these are the only two weird crashes that I've seen.

@ianlancetaylor ianlancetaylor added this to the Go1.6 milestone Feb 12, 2016
@ianlancetaylor
Copy link
Contributor

I see that your test case has no concurrency, but have you tried running it with the -race option anyhow?

@ianlancetaylor
Copy link
Contributor

Can you tell us which instruction is at the reported PC value when the program gets a SIGILL trap? You can use go test -c to get the test binary, and go tool objdump key.test to disassemble the code.

@tsuna
Copy link
Contributor Author

tsuna commented Feb 12, 2016

I ran the test several times with -race and it passed.

        hashmap.go:717  0xa918  48895c2440              MOVQ BX, 0x40(SP)
        hashmap.go:718  0xa91d  4883f800                CMPQ $0x0, AX
        hashmap.go:718  0xa921  0f8428050000            JE 0xae4f
        hashmap.go:718  0xa927  440fb6c2                MOVZX DL, R8
        hashmap.go:718  0xa92b  4983f808                CMPQ $0x8, R8
        hashmap.go:718  0xa92f  0f8313050000            JAE 0xae48
        hashmap.go:718  0xa935  4a8d2c00                LEAQ 0(AX)(R8*1), BP
        hashmap.go:718  0xa939  0fb65d00                MOVZX 0(BP), BX  // <---- here
        hashmap.go:718  0xa93d  80fb00                  CMPL $0x0, BL
        hashmap.go:718  0xa940  0f8400010000            JE 0xaa46
        hashmap.go:718  0xa946  4889442478              MOVQ AX, 0x78(SP)
        hashmap.go:718  0xa94b  8854242e                MOVL DL, 0x2e(SP)
        hashmap.go:718  0xa94f  440fb6c2                MOVZX DL, R8
        hashmap.go:718  0xa953  4983f808                CMPQ $0x8, R8
        hashmap.go:718  0xa957  0f83e4040000            JAE 0xae41
        hashmap.go:718  0xa95d  4a8d2c00                LEAQ 0(AX)(R8*1), BP
        hashmap.go:718  0xa961  0fb65d00                MOVZX 0(BP), BX
        hashmap.go:718  0xa965  80fb01                  CMPL $0x1, BL
        hashmap.go:718  0xa968  0f84d8000000            JE 0xaa46
        hashmap.go:719  0xa96e  488b5c2430              MOVQ 0x30(SP), BX

hashmap.go:718 is

        if b.tophash[offi] != empty && b.tophash[offi] != evacuatedEmpty {

@tsuna
Copy link
Contributor Author

tsuna commented Feb 12, 2016

The crash seems easily reproducible.

$ i=0; while ./key.test -test.bench . -test.run notest &>/tmp/log; do i=$((i+1)); done; echo $i
21
$ i=0; while ./key.test -test.bench . -test.run notest &>/tmp/log; do i=$((i+1)); done; echo $i
1
$ i=0; while ./key.test -test.bench . -test.run notest &>/tmp/log; do i=$((i+1)); done; echo $i
3
$ i=0; while ./key.test -test.bench . -test.run notest &>/tmp/log; do i=$((i+1)); done; echo $i
12

all of these were at the same PC=0xa939.

edit: Can repro even faster-er by passing -test.bench GetFromMapWithMapKey.

@ianlancetaylor
Copy link
Contributor

Can you try reproducing the problem on a different physical machine?

@mikioh
Copy link
Contributor

mikioh commented Feb 12, 2016

@ianlancetaylor,

Just tried and got the same result on OS X 10.11+Xcode 7.2.1.

@tsuna,

What happens if you run the test with GOGC=off? On my laptop, I don't see any crash when GOGC=off.

@ianlancetaylor
Copy link
Contributor

Interesting. I have a Intel(R) Core(TM) i7-3520M on my laptop. It's running GNU/Linux, not Darwin, but the generated instructions around where the SIGILL occurs is exactly the same. I can't recreate the problem.

Can you show us the stack trace you get if you set the environment variable GOTRACEBACK=system while running the test?

@tsuna
Copy link
Contributor Author

tsuna commented Feb 12, 2016

I reproduced this on Linux in one of our backend clusters (in an Ubuntu 15.10 Docker container running on CoreOS 835.12.0 with kernel 4.2.2-coreos-r2 on an Intel E5-2620):

go version go1.6rc2 linux/amd64

Signature is different through:

root@e65d2ed71495:/go/src/github.com/aristanetworks/goarista# i=0; while ./key.test -test.bench GetFromMapWithMapKey -test.run notest &>/tmp/log; do i=$((i+1)); done; echo $i
10
root@e65d2ed71495:/go/src/github.com/aristanetworks/goarista# cat /tmp/log
PASS
BenchmarkGetFromMapWithMapKey-24    unexpected fault address 0x0
fatal error: fault
[signal 0x7 code=0x80 addr=0x0 pc=0x409a29]

goroutine 17 [running]:
runtime.throw(0x5b9920, 0x5)
    /usr/local/go/src/runtime/panic.go:530 +0x90 fp=0xc820532600 sp=0xc8205325e8
runtime.sigpanic()
    /usr/local/go/src/runtime/sigpanic_unix.go:21 +0x10c fp=0xc820532650 sp=0xc820532600
runtime.mapiternext(0xc8200a6000)
    /usr/local/go/src/runtime/hashmap.go:718 +0x279 fp=0xc8205326e0 sp=0xc820532650
runtime.mapiterinit(0x548d60, 0xc820542000, 0xc8200a6000)
    /usr/local/go/src/runtime/hashmap.go:666 +0x2af fp=0xc820532710 sp=0xc8205326e0
reflect.mapiterinit(0x548d60, 0xc820542000, 0x15)
    /usr/local/go/src/runtime/hashmap.go:1014 +0x4a fp=0xc820532738 sp=0xc820532710
reflect.Value.MapKeys(0x548d60, 0xc820542000, 0x15, 0x0, 0x0, 0x0)
    /usr/local/go/src/reflect/value.go:1075 +0xec fp=0xc8205327f8 sp=0xc820532738
fmt.(*pp).printReflectValue(0xc8200701a0, 0x548d60, 0xc820542000, 0x15, 0x76, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:893 +0x2500 fp=0xc820532fb0 sp=0xc8205327f8
fmt.(*pp).printArg(0xc8200701a0, 0x548d60, 0xc820542000, 0x76, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:810 +0x540 fp=0xc820533138 sp=0xc820532fb0
fmt.(*pp).doPrintf(0xc8200701a0, 0x5bfcc0, 0xc, 0xc820533568, 0x1, 0x1)
    /usr/local/go/src/fmt/print.go:1238 +0x1dcd fp=0xc8205334c0 sp=0xc820533138
fmt.Sprintf(0x5bfcc0, 0xc, 0xc820533568, 0x1, 0x1, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:203 +0x6f fp=0xc820533510 sp=0xc8205334c0
github.com/aristanetworks/goarista/key.keyImpl.GoString(0x538d80, 0xc820548000, 0x0, 0x0)
    /go/src/github.com/aristanetworks/goarista/key/key.go:134 +0x110 fp=0xc8205335a8 sp=0xc820533510
github.com/aristanetworks/goarista/key.(*keyImpl).GoString(0xc8200ac1a0, 0x0, 0x0)
    <autogenerated>:8 +0xa4 fp=0xc8205335e0 sp=0xc8205335a8
fmt.(*pp).handleMethods(0xc8200700d0, 0xc800000076, 0x0, 0x1)
    /usr/local/go/src/fmt/print.go:707 +0x32e fp=0xc8205336c0 sp=0xc8205335e0
fmt.(*pp).printArg(0xc8200700d0, 0x5a46c0, 0xc8200ac1a0, 0x76, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:806 +0x4a9 fp=0xc820533848 sp=0xc8205336c0
fmt.(*pp).doPrintf(0xc8200700d0, 0x5bd5b0, 0x8, 0xc820533d90, 0x1, 0x1)
    /usr/local/go/src/fmt/print.go:1238 +0x1dcd fp=0xc820533bd0 sp=0xc820533848
fmt.Sprintf(0x5bd5b0, 0x8, 0xc820533d90, 0x1, 0x1, 0x0, 0x0)
    /usr/local/go/src/fmt/print.go:203 +0x6f fp=0xc820533c20 sp=0xc820533bd0
testing.(*common).Fatalf(0xc8200d2000, 0x5bd5b0, 0x8, 0xc820533d90, 0x1, 0x1)
    /usr/local/go/src/testing/testing.go:388 +0x49 fp=0xc820533c70 sp=0xc820533c20
github.com/aristanetworks/goarista/key_test.BenchmarkGetFromMapWithMapKey(0xc8200d2000)
    /go/src/github.com/aristanetworks/goarista/key/key_test.go:500 +0x2275 fp=0xc820533f20 sp=0xc820533c70
testing.(*B).runN(0xc8200d2000, 0x7a120)
    /usr/local/go/src/testing/benchmark.go:135 +0x9a fp=0xc820533f40 sp=0xc820533f20
testing.(*B).launch(0xc8200d2000)
    /usr/local/go/src/testing/benchmark.go:227 +0x131 fp=0xc820533f98 sp=0xc820533f40
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820533fa0 sp=0xc820533f98
created by testing.(*B).run
    /usr/local/go/src/testing/benchmark.go:190 +0x54

goroutine 1 [chan receive]:
testing.(*B).run(0xc8200d2000, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/go/src/testing/benchmark.go:191 +0x7b
testing.RunBenchmarks(0x6073a0, 0x69ba80, 0x3, 0x3)
    /usr/local/go/src/testing/benchmark.go:343 +0x76c
testing.(*M).Run(0xc820053ef8, 0xffffffffffffffff)
    /usr/local/go/src/testing/testing.go:524 +0x1c9
main.main()
    github.com/aristanetworks/goarista/key/_test/_testmain.go:74 +0x117

That PC is the same instruction:

    hashmap.go:718  0x409a29    0fb65d00        MOVZX 0(BP), BX

@tsuna
Copy link
Contributor Author

tsuna commented Feb 12, 2016

@mikioh I've run 123 iterations of the above command with GOGC=off and haven't seen any crashes.

@ianlancetaylor here's the output with GOTRACEBACK=system

PASS
BenchmarkGetFromMapWithMapKey-8 SIGILL: illegal instruction
PC=0xa939 m=2

goroutine 5 [running]:
runtime.mapiternext(0x820308120)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:718 +0x279 fp=0x8203b86e0 sp=0x8203b8650
runtime.mapiterinit(0x147820, 0x82075a000, 0x820308120)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:666 +0x2af fp=0x8203b8710 sp=0x8203b86e0
reflect.mapiterinit(0x147820, 0x82075a000, 0x15)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:1014 +0x4a fp=0x8203b8738 sp=0x8203b8710
reflect.Value.MapKeys(0x147820, 0x82075a000, 0x15, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/reflect/value.go:1075 +0xec fp=0x8203b87f8 sp=0x8203b8738
fmt.(*pp).printReflectValue(0x82034c1a0, 0x147820, 0x82075a000, 0x15, 0x76, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:893 +0x2500 fp=0x8203b8fb0 sp=0x8203b87f8
fmt.(*pp).printArg(0x82034c1a0, 0x147820, 0x82075a000, 0x76, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:810 +0x540 fp=0x8203b9138 sp=0x8203b8fb0
fmt.(*pp).doPrintf(0x82034c1a0, 0x1bdf90, 0xc, 0x8203b9568, 0x1, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:1238 +0x1dcd fp=0x8203b94c0 sp=0x8203b9138
fmt.Sprintf(0x1bdf90, 0xc, 0x8203b9568, 0x1, 0x1, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:203 +0x6f fp=0x8203b9510 sp=0x8203b94c0
github.com/aristanetworks/goarista/key.keyImpl.GoString(0x1380e0, 0x820764000, 0x0, 0x0)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/key/key.go:134 +0x110 fp=0x8203b95a8 sp=0x8203b9510
github.com/aristanetworks/goarista/key.(*keyImpl).GoString(0x8207a6010, 0x0, 0x0)
    <autogenerated>:8 +0xa4 fp=0x8203b95e0 sp=0x8203b95a8
fmt.(*pp).handleMethods(0x82034c0d0, 0x800000076, 0x0, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:707 +0x32e fp=0x8203b96c0 sp=0x8203b95e0
fmt.(*pp).printArg(0x82034c0d0, 0x1a2e40, 0x8207a6010, 0x76, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:806 +0x4a9 fp=0x8203b9848 sp=0x8203b96c0
fmt.(*pp).doPrintf(0x82034c0d0, 0x1bb9a0, 0x8, 0x8203b9d90, 0x1, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:1238 +0x1dcd fp=0x8203b9bd0 sp=0x8203b9848
fmt.Sprintf(0x1bb9a0, 0x8, 0x8203b9d90, 0x1, 0x1, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:203 +0x6f fp=0x8203b9c20 sp=0x8203b9bd0
testing.(*common).Fatalf(0x82038e000, 0x1bb9a0, 0x8, 0x8203b9d90, 0x1, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:388 +0x49 fp=0x8203b9c70 sp=0x8203b9c20
github.com/aristanetworks/goarista/key_test.BenchmarkGetFromMapWithMapKey(0x82038e000)
    /Users/tsuna/go/src/github.com/aristanetworks/goarista/key/key_test.go:500 +0x2275 fp=0x8203b9f20 sp=0x8203b9c70
testing.(*B).runN(0x82038e000, 0xf4240)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:135 +0x9a fp=0x8203b9f40 sp=0x8203b9f20
testing.(*B).launch(0x82038e000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:227 +0x131 fp=0x8203b9f98 sp=0x8203b9f40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x8203b9fa0 sp=0x8203b9f98
created by testing.(*B).run
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:190 +0x54

goroutine 1 [chan receive]:
runtime.gopark(0x204e88, 0x8203083b8, 0x1bccb0, 0xc, 0x17, 0x3)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x8203319f0 sp=0x8203319c8
runtime.goparkunlock(0x8203083b8, 0x1bccb0, 0xc, 0x82034cd17, 0x3)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x820331a28 sp=0x8203319f0
runtime.chanrecv(0x13fd00, 0x820308360, 0x0, 0x820331a01, 0x70000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/chan.go:470 +0x49f fp=0x820331ab0 sp=0x820331a28
runtime.chanrecv1(0x13fd00, 0x820308360, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/chan.go:355 +0x2b fp=0x820331ae0 sp=0x820331ab0
testing.(*B).run(0x82038e000, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:191 +0x7b fp=0x820331b00 sp=0x820331ae0
testing.RunBenchmarks(0x204b50, 0x29aa40, 0x3, 0x3)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:343 +0x76c fp=0x820331dd0 sp=0x820331b00
testing.(*M).Run(0x820331ef8, 0xffffffffffffffff)
    /usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:524 +0x1c9 fp=0x820331e58 sp=0x820331dd0
main.main()
    github.com/aristanetworks/goarista/key/_test/_testmain.go:74 +0x117 fp=0x820331f50 sp=0x820331e58
runtime.main()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:188 +0x2b0 fp=0x820331fa0 sp=0x820331f50
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x820331fa8 sp=0x820331fa0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x204e88, 0x29cd60, 0x1bd5c0, 0xf, 0x14, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031a758 sp=0x82031a730
runtime.goparkunlock(0x29cd60, 0x1bd5c0, 0xf, 0x8202f0114, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x82031a790 sp=0x82031a758
runtime.forcegchelper()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:229 +0xb8 fp=0x82031a7c0 sp=0x82031a790
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031a7c8 sp=0x82031a7c0
created by runtime.init.4
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:218 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x204e88, 0x29cee0, 0x1bac20, 0xd, 0x4e214, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031af48 sp=0x82031af20
runtime.goparkunlock(0x29cee0, 0x1bac20, 0xd, 0x14, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x82031af80 sp=0x82031af48
runtime.bgsweep(0x820342000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgcsweep.go:79 +0x14d fp=0x82031afb8 sp=0x82031af80
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031afc0 sp=0x82031afb8
created by runtime.gcenable
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:191 +0x53

goroutine 4 [finalizer wait]:
runtime.gopark(0x204e88, 0x2b74f8, 0x1bd240, 0xe, 0x14, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031b718 sp=0x82031b6f0
runtime.goparkunlock(0x2b74f8, 0x1bd240, 0xe, 0x14, 0x1)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x82031b750 sp=0x82031b718
runtime.runfinq()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mfinal.go:158 +0xaa fp=0x82031b7c0 sp=0x82031b750
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031b7c8 sp=0x82031b7c0
created by runtime.createfing
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mfinal.go:139 +0x60

goroutine 6 [GC worker (idle)]:
runtime.gopark(0x82073bce0, 0x820318fa0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x820318f40 sp=0x820318f18
runtime.gcBgMarkWorker(0x82030a000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x820318fb8 sp=0x820318f40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x820318fc0 sp=0x820318fb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 7 [GC worker (idle)]:
runtime.gopark(0x8207a8030, 0x8203197a0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x820319740 sp=0x820319718
runtime.gcBgMarkWorker(0x82030b500)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x8203197b8 sp=0x820319740
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x8203197c0 sp=0x8203197b8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 8 [GC worker (idle)]:
runtime.gopark(0x820754028, 0x820319fa0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x820319f40 sp=0x820319f18
runtime.gcBgMarkWorker(0x82030ca00)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x820319fb8 sp=0x820319f40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x820319fc0 sp=0x820319fb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 9 [GC worker (idle)]:
runtime.gopark(0x820300610, 0x82031c7a0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031c740 sp=0x82031c718
runtime.gcBgMarkWorker(0x82030e000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031c7b8 sp=0x82031c740
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031c7c0 sp=0x82031c7b8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 10 [GC worker (idle)]:
runtime.gopark(0x8207a8020, 0x82031cfa0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031cf40 sp=0x82031cf18
runtime.gcBgMarkWorker(0x82030f500)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031cfb8 sp=0x82031cf40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031cfc0 sp=0x82031cfb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 11 [GC worker (idle)]:
runtime.gopark(0x820760000, 0x82031d7a0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031d740 sp=0x82031d718
runtime.gcBgMarkWorker(0x820310a00)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031d7b8 sp=0x82031d740
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031d7c0 sp=0x82031d7b8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 12 [GC worker (idle)]:
runtime.gopark(0x8207a6000, 0x82031dfa0, 0x1d4f70, 0x10, 0x14, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031df40 sp=0x82031df18
runtime.gcBgMarkWorker(0x820312000)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031dfb8 sp=0x82031df40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031dfc0 sp=0x82031dfb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 13 [GC worker (idle)]:
runtime.gopark(0x8207a8000, 0x82031bfa0, 0x1d4f70, 0x10, 0x82038e014, 0x0)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031bf40 sp=0x82031bf18
runtime.gcBgMarkWorker(0x820313500)
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031bfb8 sp=0x82031bf40
runtime.goexit()
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031bfc0 sp=0x82031bfb8
created by runtime.gcBgMarkStartWorkers
    /usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

rax    0xdd3bd550f5ae4a00
rbx    0xdd3bd550f5ae4a88
rcx    0x8202f1080
rdx    0x0
rdi    0x203d40
rsi    0x147820
rbp    0xdd3bd550f5ae4a00
rsp    0x8203b8650
r8     0x0
r9     0x0
r10    0xdd3bd550f5ae4a08
r11    0x0
r12    0x8
r13    0x203d3f
r14    0xf
r15    0x8
rip    0xa939
rflags 0x10293
cs     0x2b
fs     0x0
gs     0x0

@tsuna tsuna changed the title runtime: SIGILL in runtime.mapiternext on darwin/amd64 with 1.6rc2 runtime: SIGILL in runtime.mapiternext on amd64 with 1.6rc2 Feb 12, 2016
@ianlancetaylor
Copy link
Contributor

If this only happens when the GC is running then I wonder if the stack is somehow shrinking at a bad time.

Does it happen if you let the GC run as usual but set the environment variable GODEBUG=gcshrinkstackoff=1 ?

CC @randall77 @aclements

@tsuna
Copy link
Contributor Author

tsuna commented Feb 12, 2016

Yes this happens with GODEBUG=gcshrinkstackoff=1. I confirm that GOGC=off seems to neuter the crash, I was able to run another 723 iterations without seeing any crash.

@davecheney
Copy link
Contributor

I've confirmed this on linux/amd64, rev

unexpected fault address 0x0
fatal error: fault
[signal 0x7 code=0x80 addr=0x0 pc=0x409a29]

goroutine 19 [running]:
runtime.throw(0x5b63a8, 0x5)
        /home/dfc/go/src/runtime/panic.go:530 +0x90 fp=0xc8202f05d0
sp=0xc8202f05b8
runtime.sigpanic()
        /home/dfc/go/src/runtime/sigpanic_unix.go:21 +0x10c fp=0xc8202f0620
sp=0xc8202f05d0
runtime.mapiternext(0xc8200fe0c0)
        /home/dfc/go/src/runtime/hashmap.go:718 +0x279 fp=0xc8202f06b0
sp=0xc8202f0620
runtime.mapiterinit(0x545d60, 0xc8203ca000, 0xc8200fe0c0)
        /home/dfc/go/src/runtime/hashmap.go:666 +0x2af fp=0xc8202f06e0
sp=0xc8202f06b0
reflect.mapiterinit(0x545d60, 0xc8203ca000, 0x15)
        /home/dfc/go/src/runtime/hashmap.go:1014 +0x4a fp=0xc8202f0708
sp=0xc8202f06e0
reflect.Value.MapKeys(0x545d60, 0xc8203ca000, 0x15, 0x0, 0x0, 0x0)
        /home/dfc/go/src/reflect/value.go:1075 +0xec fp=0xc8202f07c8
sp=0xc8202f0708
fmt.(*pp).printReflectValue(0xc8201061a0, 0x545d60, 0xc8203ca000, 0x15,
0x76, 0x0, 0x0)
        /home/dfc/go/src/fmt/print.go:893 +0x2500 fp=0xc8202f0f80
sp=0xc8202f07c8
fmt.(*pp).printArg(0xc8201061a0, 0x545d60, 0xc8203ca000, 0x76, 0x0, 0x0)
        /home/dfc/go/src/fmt/print.go:810 +0x540 fp=0xc8202f1108
sp=0xc8202f0f80
fmt.(*pp).doPrintf(0xc8201061a0, 0x5bc6d0, 0xc, 0xc8202f1538, 0x1, 0x1)
        /home/dfc/go/src/fmt/print.go:1238 +0x1dcd fp=0xc8202f1490
sp=0xc8202f1108
fmt.Sprintf(0x5bc6d0, 0xc, 0xc8202f1538, 0x1, 0x1, 0x0, 0x0)
        /home/dfc/go/src/fmt/print.go:203 +0x6f fp=0xc8202f14e0
sp=0xc8202f1490
github.com/aristanetworks/goarista/key.keyImpl.GoString(0x535d80,
0xc8203ce000, 0x0, 0x0)
        /home/dfc/src/github.com/aristanetworks/goarista/key/key.go:134
+0x110 fp=0xc8202f1578 sp=0xc8202f14e0
github.com/aristanetworks/goarista/key.(*keyImpl).GoString(0xc82047c000,
0x0, 0x0)
        <autogenerated>:8 +0xa4 fp=0xc8202f15b0 sp=0xc8202f1578
fmt.(*pp).handleMethods(0xc820106270, 0xc800000076, 0x0, 0xc820106101)
        /home/dfc/go/src/fmt/print.go:707 +0x32e fp=0xc8202f1690
sp=0xc8202f15b0
fmt.(*pp).printArg(0xc820106270, 0x5a1140, 0xc82047c000, 0x76, 0x0, 0x0)
        /home/dfc/go/src/fmt/print.go:806 +0x4a9 fp=0xc8202f1818
sp=0xc8202f1690
fmt.(*pp).doPrintf(0xc820106270, 0x5ba010, 0x8, 0xc8202f1d70, 0x1, 0x1)
        /home/dfc/go/src/fmt/print.go:1238 +0x1dcd fp=0xc8202f1ba0
sp=0xc8202f1818
fmt.Sprintf(0x5ba010, 0x8, 0xc8202f1d70, 0x1, 0x1, 0x0, 0x0)
        /home/dfc/go/src/fmt/print.go:203 +0x6f fp=0xc8202f1bf0
sp=0xc8202f1ba0
testing.(*common).Fatalf(0xc820152000, 0x5ba010, 0x8, 0xc8202f1d70, 0x1,
0x1)
        /home/dfc/go/src/testing/testing.go:388 +0x49 fp=0xc8202f1c40
sp=0xc8202f1bf0
github.com/aristanetworks/goarista/key_test.BenchmarkGetFromMapWithMapKey(0xc820152000)
        /home/dfc/src/github.com/aristanetworks/goarista/key/key_test.go:423
+0x2361 fp=0xc8202f1f20 sp=0xc8202f1c40
testing.(*B).runN(0xc820152000, 0x7a120)
        /home/dfc/go/src/testing/benchmark.go:135 +0x9a fp=0xc8202f1f40
sp=0xc8202f1f20
testing.(*B).launch(0xc820152000)
        /home/dfc/go/src/testing/benchmark.go:227 +0x131 fp=0xc8202f1f98
sp=0xc8202f1f40
runtime.goexit()
        /home/dfc/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc8202f1fa0
sp=0xc8202f1f98
created by testing.(*B).run
        /home/dfc/go/src/testing/benchmark.go:190 +0x54

goroutine 1 [chan receive]:
testing.(*B).run(0xc820152000, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/dfc/go/src/testing/benchmark.go:191 +0x7b
testing.RunBenchmarks(0x602f68, 0x697a80, 0x3, 0x3)
        /home/dfc/go/src/testing/benchmark.go:343 +0x76c
testing.(*M).Run(0xc8200cbef8, 0xffffffffffffffff)
        /home/dfc/go/src/testing/testing.go:524 +0x1c9
main.main()
        github.com/aristanetworks/goarista/key/_test/_testmain.go:72 +0x117

% go version
go version devel +fa5e547 Sun Feb 7 03:18:28 2016 +0000 linux/amd64

On Fri, Feb 12, 2016 at 6:17 PM, Benoit Sigoure notifications@github.com
wrote:

@mikioh https://github.com/mikioh I've run 123 iterations of the above
command with GOGC=off and haven't seen any crashes.

@ianlancetaylor https://github.com/ianlancetaylor here's the output
with GOTRACEBACK=system

PASS
BenchmarkGetFromMapWithMapKey-8 SIGILL: illegal instruction
PC=0xa939 m=2

goroutine 5 [running]:
runtime.mapiternext(0x820308120)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:718 +0x279 fp=0x8203b86e0 sp=0x8203b8650
runtime.mapiterinit(0x147820, 0x82075a000, 0x820308120)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:666 +0x2af fp=0x8203b8710 sp=0x8203b86e0
reflect.mapiterinit(0x147820, 0x82075a000, 0x15)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/hashmap.go:1014 +0x4a fp=0x8203b8738 sp=0x8203b8710
reflect.Value.MapKeys(0x147820, 0x82075a000, 0x15, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/reflect/value.go:1075 +0xec fp=0x8203b87f8 sp=0x8203b8738
fmt.(_pp).printReflectValue(0x82034c1a0, 0x147820, 0x82075a000, 0x15, 0x76, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:893 +0x2500 fp=0x8203b8fb0 sp=0x8203b87f8
fmt.(_pp).printArg(0x82034c1a0, 0x147820, 0x82075a000, 0x76, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:810 +0x540 fp=0x8203b9138 sp=0x8203b8fb0
fmt.(_pp).doPrintf(0x82034c1a0, 0x1bdf90, 0xc, 0x8203b9568, 0x1, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:1238 +0x1dcd fp=0x8203b94c0 sp=0x8203b9138
fmt.Sprintf(0x1bdf90, 0xc, 0x8203b9568, 0x1, 0x1, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:203 +0x6f fp=0x8203b9510 sp=0x8203b94c0github.com/aristanetworks/goarista/key.keyImpl.GoString(0x1380e0, 0x820764000, 0x0, 0x0)
/Users/tsuna/go/src/github.com/aristanetworks/goarista/key/key.go:134 +0x110 fp=0x8203b95a8 sp=0x8203b9510github.com/aristanetworks/goarista/key.(_keyImpl).GoString(0x8207a6010, 0x0, 0x0)
:8 +0xa4 fp=0x8203b95e0 sp=0x8203b95a8
fmt.(_pp).handleMethods(0x82034c0d0, 0x800000076, 0x0, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:707 +0x32e fp=0x8203b96c0 sp=0x8203b95e0
fmt.(_pp).printArg(0x82034c0d0, 0x1a2e40, 0x8207a6010, 0x76, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:806 +0x4a9 fp=0x8203b9848 sp=0x8203b96c0
fmt.(_pp).doPrintf(0x82034c0d0, 0x1bb9a0, 0x8, 0x8203b9d90, 0x1, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:1238 +0x1dcd fp=0x8203b9bd0 sp=0x8203b9848
fmt.Sprintf(0x1bb9a0, 0x8, 0x8203b9d90, 0x1, 0x1, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/fmt/print.go:203 +0x6f fp=0x8203b9c20 sp=0x8203b9bd0
testing.(_common).Fatalf(0x82038e000, 0x1bb9a0, 0x8, 0x8203b9d90, 0x1, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:388 +0x49 fp=0x8203b9c70 sp=0x8203b9c20github.com/aristanetworks/goarista/key_test.BenchmarkGetFromMapWithMapKey(0x82038e000)
/Users/tsuna/go/src/github.com/aristanetworks/goarista/key/key_test.go:500 +0x2275 fp=0x8203b9f20 sp=0x8203b9c70
testing.(_B).runN(0x82038e000, 0xf4240)
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:135 +0x9a fp=0x8203b9f40 sp=0x8203b9f20
testing.(_B).launch(0x82038e000)
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:227 +0x131 fp=0x8203b9f98 sp=0x8203b9f40
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x8203b9fa0 sp=0x8203b9f98
created by testing.(*B).run
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:190 +0x54

goroutine 1 [chan receive]:
runtime.gopark(0x204e88, 0x8203083b8, 0x1bccb0, 0xc, 0x17, 0x3)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x8203319f0 sp=0x8203319c8
runtime.goparkunlock(0x8203083b8, 0x1bccb0, 0xc, 0x82034cd17, 0x3)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x820331a28 sp=0x8203319f0
runtime.chanrecv(0x13fd00, 0x820308360, 0x0, 0x820331a01, 0x70000)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/chan.go:470 +0x49f fp=0x820331ab0 sp=0x820331a28
runtime.chanrecv1(0x13fd00, 0x820308360, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/chan.go:355 +0x2b fp=0x820331ae0 sp=0x820331ab0
testing.(_B).run(0x82038e000, 0x0, 0x0, 0x0, 0x0, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:191 +0x7b fp=0x820331b00 sp=0x820331ae0
testing.RunBenchmarks(0x204b50, 0x29aa40, 0x3, 0x3)
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/benchmark.go:343 +0x76c fp=0x820331dd0 sp=0x820331b00
testing.(_M).Run(0x820331ef8, 0xffffffffffffffff)
/usr/local/Cellar/go/1.6rc2/libexec/src/testing/testing.go:524 +0x1c9 fp=0x820331e58 sp=0x820331dd0
main.main()
github.com/aristanetworks/goarista/key/_test/_testmain.go:74 +0x117 fp=0x820331f50 sp=0x820331e58
runtime.main()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:188 +0x2b0 fp=0x820331fa0 sp=0x820331f50
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x820331fa8 sp=0x820331fa0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x204e88, 0x29cd60, 0x1bd5c0, 0xf, 0x14, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031a758 sp=0x82031a730
runtime.goparkunlock(0x29cd60, 0x1bd5c0, 0xf, 0x8202f0114, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x82031a790 sp=0x82031a758
runtime.forcegchelper()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:229 +0xb8 fp=0x82031a7c0 sp=0x82031a790
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031a7c8 sp=0x82031a7c0
created by runtime.init.4
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:218 +0x2b

goroutine 3 [GC sweep wait]:
runtime.gopark(0x204e88, 0x29cee0, 0x1bac20, 0xd, 0x4e214, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031af48 sp=0x82031af20
runtime.goparkunlock(0x29cee0, 0x1bac20, 0xd, 0x14, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x82031af80 sp=0x82031af48
runtime.bgsweep(0x820342000)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgcsweep.go:79 +0x14d fp=0x82031afb8 sp=0x82031af80
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031afc0 sp=0x82031afb8
created by runtime.gcenable
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:191 +0x53

goroutine 4 [finalizer wait]:
runtime.gopark(0x204e88, 0x2b74f8, 0x1bd240, 0xe, 0x14, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031b718 sp=0x82031b6f0
runtime.goparkunlock(0x2b74f8, 0x1bd240, 0xe, 0x14, 0x1)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:268 +0x54 fp=0x82031b750 sp=0x82031b718
runtime.runfinq()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mfinal.go:158 +0xaa fp=0x82031b7c0 sp=0x82031b750
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031b7c8 sp=0x82031b7c0
created by runtime.createfing
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mfinal.go:139 +0x60

goroutine 6 [GC worker (idle)]:
runtime.gopark(0x82073bce0, 0x820318fa0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x820318f40 sp=0x820318f18
runtime.gcBgMarkWorker(0x82030a000)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x820318fb8 sp=0x820318f40
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x820318fc0 sp=0x820318fb8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 7 [GC worker (idle)]:
runtime.gopark(0x8207a8030, 0x8203197a0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x820319740 sp=0x820319718
runtime.gcBgMarkWorker(0x82030b500)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x8203197b8 sp=0x820319740
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x8203197c0 sp=0x8203197b8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 8 [GC worker (idle)]:
runtime.gopark(0x820754028, 0x820319fa0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x820319f40 sp=0x820319f18
runtime.gcBgMarkWorker(0x82030ca00)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x820319fb8 sp=0x820319f40
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x820319fc0 sp=0x820319fb8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 9 [GC worker (idle)]:
runtime.gopark(0x820300610, 0x82031c7a0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031c740 sp=0x82031c718
runtime.gcBgMarkWorker(0x82030e000)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031c7b8 sp=0x82031c740
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031c7c0 sp=0x82031c7b8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 10 [GC worker (idle)]:
runtime.gopark(0x8207a8020, 0x82031cfa0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031cf40 sp=0x82031cf18
runtime.gcBgMarkWorker(0x82030f500)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031cfb8 sp=0x82031cf40
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031cfc0 sp=0x82031cfb8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 11 [GC worker (idle)]:
runtime.gopark(0x820760000, 0x82031d7a0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031d740 sp=0x82031d718
runtime.gcBgMarkWorker(0x820310a00)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031d7b8 sp=0x82031d740
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031d7c0 sp=0x82031d7b8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 12 [GC worker (idle)]:
runtime.gopark(0x8207a6000, 0x82031dfa0, 0x1d4f70, 0x10, 0x14, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031df40 sp=0x82031df18
runtime.gcBgMarkWorker(0x820312000)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031dfb8 sp=0x82031df40
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031dfc0 sp=0x82031dfb8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

goroutine 13 [GC worker (idle)]:
runtime.gopark(0x8207a8000, 0x82031bfa0, 0x1d4f70, 0x10, 0x82038e014, 0x0)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/proc.go:262 +0x163 fp=0x82031bf40 sp=0x82031bf18
runtime.gcBgMarkWorker(0x820313500)
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1402 +0xda fp=0x82031bfb8 sp=0x82031bf40
runtime.goexit()
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/asm_amd64.s:1998 +0x1 fp=0x82031bfc0 sp=0x82031bfb8
created by runtime.gcBgMarkStartWorkers
/usr/local/Cellar/go/1.6rc2/libexec/src/runtime/mgc.go:1329 +0x92

rax 0xdd3bd550f5ae4a00
rbx 0xdd3bd550f5ae4a88
rcx 0x8202f1080
rdx 0x0
rdi 0x203d40
rsi 0x147820
rbp 0xdd3bd550f5ae4a00
rsp 0x8203b8650
r8 0x0
r9 0x0
r10 0xdd3bd550f5ae4a08
r11 0x0
r12 0x8
r13 0x203d3f
r14 0xf
r15 0x8
rip 0xa939
rflags 0x10293
cs 0x2b
fs 0x0
gs 0x0


Reply to this email directly or view it on GitHub
#14306 (comment).

@davecheney
Copy link
Contributor

Looking into this further, the crash happens here

                _, found := key.GetFromMap(m)
                if !found {
                        b.Fatalf("WTF: %#v", key) // here
                }

That is, in the case that should not happen. The key value may be somehow corrupt, because if we remove the printing of the key from the b.Fatal, eventually we get:

BenchmarkGetFromMapWithMapKey-80 --- FAIL: BenchmarkGetFromMapWithMapKey-80
key_test.go:423: WTF: key not found

I thought this was a liveness issue, but moving the key declaration to the package scope does not solve the problem:

        for i := 0; i < b.N; i++ {
                key = New(map[string]interface{}{fmt.Sprintf("a%d", i%19): true})
                _, found := key.GetFromMap(m)
                if !found {
                        b.Fatalf("WTF: key not found")
                }
        }
}

var key Key

BenchmarkGetFromMapWithMapKey-119 --- FAIL: BenchmarkGetFromMapWithMapKey-119
key_test.go:423: WTF: key not found

@davecheney
Copy link
Contributor

Neither -l nor -N fixes the error from the key not being found in the map.

@davecheney
Copy link
Contributor

I have extracted a repo, http://play.golang.org/p/L4AQ2hPIB0

This fails quickly run with a random GOMAXPROCS while true; do env GOMAXPROCS=$[ 1 + $[ RANDOM % 128 ]] ./xxx; done

The program should not exit with the WTF message, that means the key constructed was not found in the map, printing the key will most likely cause a more serious panic because its values are garbage.

@randall77
Copy link
Contributor

My guess at this point is a missing write barrier. It's in the New function of Dave's repo:

func New(intf interface{}) KeyImpl {
    switch t := intf.(type) {
    case map[string]interface{}:
        intf = &t
    default:
        panic(fmt.Sprintf("Invalid type for key: %T", intf))
    }
    return KeyImpl{key: intf}
}

Since we take the address of t and that address is returned, t is heap allocated. When t is initialized with t := intf.(type), we allocate a chunk of memory using newobject (the type being map[string]interface{}) and store the data portion of the interface to it. That write does not have a write barrier, and I think it should.

@randall77
Copy link
Contributor

Fix out for review: https://go-review.googlesource.com/#/c/19481/

@gopherbot
Copy link

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

@golang golang locked and limited conversation to collaborators Feb 28, 2017
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