runtime/pprof: segmentation fault

[bradfitz]

A number of builds and trybots have failed recently with:

signal: segmentation fault
FAIL    runtime/pprof   16.870s

linux-amd64-race:
http://build.golang.org/log/60268e3ff9d00b59c53a8ab7a157f62c92a32694
http://build.golang.org/log/791514375c93966427c693becc4a52c72ae0b0a3

linux-386:
https://storage.googleapis.com/go-build-log/cd8e2e9b/linux-386_5f49e79a.log

/cc @dvyukov @rsc @aclements

[aclements]

This is the earliest instance I was able to find:
http://build.golang.org/log/008781cce514f74816f8943980c16cc66cf7085b
This is on the linux-amd64 builder, commit 4b956ae.

Taking a stab in the dark, I would guess this is happening in the trace verifier and that it's some assumption I broke in the commits leading up to that one. I bet this would be easy to track down if we had a stack trace for the failure, but I haven't been able to reproduce it locally (even on linux-amd64). Any idea why we're not getting a stack trace?

[bradfitz]

Perhaps it's because GOTRACEBACK isn't set to 2 on the builders and it's the runtime itself that's crashing?

[aclements]

Possibly related: various builders are sometimes failing with

'''
--- FAIL: TestTraceStressStartStop (0.13s)
trace_test.go:358: failed to parse trace: g 5 is not waiting during syscall exit (offset 18799, time 0)
FAIL
FAIL runtime/pprof 10.417s
'''

Started around the same time.

linux-386
eec6fdc http://build.golang.org/log/15aee0932bd5116301b28e6cb46355be3633502a

windows-amd64-2003kardianos
eec6fdc http://build.golang.org/log/c1728f188a06c500fe4761739559e7a6ed0e8a6e

linux-amd64-nocgo
2f14b16 http://build.golang.org/log/d37edb40233f36c177e1b1267555b6bdc8f677ed

[aclements]

Actually, I found the "failed to parse trace" failures back to 089d363, which looks likely to be related to that commit. So that's probably a red herring.

[aclements]

Finally got a stack trace using gomote (yay gomote). I think I know what's wrong and I'm working on it.

fatal error: unexpected signal during runtime execution
[signal 0xb code=0x2 addr=0x80550c2 pc=0x809019c]

runtime stack:
runtime.throw(0x823bca8, 0x2a)
    /tmp/buildlet-scatch821635628/go/src/runtime/panic.go:543 +0x7f fp=0xf089d2c8 sp=0xf089d2bc
runtime.sigpanic()
    /tmp/buildlet-scatch821635628/go/src/runtime/sigpanic_unix.go:12 +0x5c fp=0xf089d2f4 sp=0xf089d2c8
runtime.cas(0x80550c2, 0x1, 0x2)
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:465 +0xc fp=0xf089d2f8 sp=0xf089d2f4
runtime.casgstatus(0x8055082, 0x1, 0x2)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc1.go:360 +0x55 fp=0xf089d318 sp=0xf089d2f8
runtime.execute(0x8055082)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc1.go:1237 +0x49 fp=0xf089d32c sp=0xf089d318
runtime.readyExecute.func1(0x18501180)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc1.go:185 +0x168 fp=0xf089d340 sp=0xf089d32c
runtime.mcall(0xf77443c0)
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:210 +0x47 fp=0xf089d348 sp=0xf089d340

goroutine 1 [chan receive]:
runtime.gopark(0x825db84, 0x185af530, 0x8210988, 0xc, 0x17, 0x3)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1851bdb4 sp=0x1851bd9c
runtime.goparkunlock(0x185af530, 0x8210988, 0xc, 0x17, 0x3)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x1851bdd0 sp=0x1851bdb4
runtime.chanrecv(0x81a2ac0, 0x185af500, 0x1851bedc, 0x18533e01, 0x80a0000)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:434 +0x3ce fp=0x1851be38 sp=0x1851bdd0
runtime.chanrecv1(0x81a2ac0, 0x185af500, 0x1851bedc)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:335 +0x24 fp=0x1851be50 sp=0x1851be38
testing.RunTests(0x825d908, 0x82f4360, 0xe, 0xe, 0x1856a001)
    /tmp/buildlet-scatch821635628/go/src/testing/testing.go:561 +0x880 fp=0x1851bf20 sp=0x1851be50
testing.(*M).Run(0x18510150, 0x830b0c0)
    /tmp/buildlet-scatch821635628/go/src/testing/testing.go:490 +0x6b fp=0x1851bf64 sp=0x1851bf20
main.main()
    /tmp/go-build327196867/runtime/pprof/_test/_testmain.go:82 +0x177 fp=0x1851bfc8 sp=0x1851bf64
runtime.main()
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:107 +0x25b fp=0x1851bff0 sp=0x1851bfc8
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851bff4 sp=0x1851bff0

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x18532ff4 sp=0x18532ff0

goroutine 2 [force gc (idle)]:
runtime.gopark(0x825db84, 0x82f58a0, 0x8211068, 0xf, 0x82f5e14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1851e7bc sp=0x1851e7a4
runtime.goparkunlock(0x82f58a0, 0x8211068, 0xf, 0x18500014, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x1851e7d8 sp=0x1851e7bc
runtime.forcegchelper()
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:148 +0xaf fp=0x1851e7f0 sp=0x1851e7d8
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851e7f4 sp=0x1851e7f0
created by runtime.init.4
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:137 +0x31

goroutine 3 [GC sweep wait]:
runtime.gopark(0x825db84, 0x82f5960, 0x820f3c8, 0xd, 0x8088d14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1851efb0 sp=0x1851ef98
runtime.goparkunlock(0x82f5960, 0x820f3c8, 0xd, 0x14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x1851efcc sp=0x1851efb0
runtime.bgsweep(0x185140c0)
    /tmp/buildlet-scatch821635628/go/src/runtime/mgcsweep.go:67 +0x12a fp=0x1851efe8 sp=0x1851efcc
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851efec sp=0x1851efe8
created by runtime.gcenable
    /tmp/buildlet-scatch821635628/go/src/runtime/mgc.go:166 +0x59

goroutine 4 [finalizer wait]:
runtime.gopark(0x825db84, 0x830b2d8, 0x8210e28, 0xe, 0x14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1851f79c sp=0x1851f784
runtime.goparkunlock(0x830b2d8, 0x8210e28, 0xe, 0x14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x1851f7b8 sp=0x1851f79c
runtime.runfinq()
    /tmp/buildlet-scatch821635628/go/src/runtime/mfinal.go:149 +0xa3 fp=0x1851f7f0 sp=0x1851f7b8
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851f7f4 sp=0x1851f7f0
created by runtime.createfing
    /tmp/buildlet-scatch821635628/go/src/runtime/mfinal.go:130 +0x63

goroutine 5 [syscall]:
runtime.notetsleepg(0x82f59ec, 0x31a868f9, 0x1a, 0x4)
    /tmp/buildlet-scatch821635628/go/src/runtime/lock_futex.go:198 +0x54 fp=0x1851ff90 sp=0x1851ff78
runtime.timerproc()
    /tmp/buildlet-scatch821635628/go/src/runtime/time.go:209 +0xed fp=0x1851fff0 sp=0x1851ff90
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851fff4 sp=0x1851fff0
created by runtime.addtimerLocked
    /tmp/buildlet-scatch821635628/go/src/runtime/time.go:116 +0x19a

goroutine 62 [chan receive]:
runtime.gopark(0x825db84, 0x185af570, 0x8210988, 0xc, 0x17, 0x3)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1851ceb0 sp=0x1851ce98
runtime.goparkunlock(0x185af570, 0x8210988, 0xc, 0x17, 0x3)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x1851cecc sp=0x1851ceb0
runtime.chanrecv(0x81a2a00, 0x185af540, 0x0, 0x1, 0xffff0000)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:434 +0x3ce fp=0x1851cf34 sp=0x1851cecc
runtime.chanrecv1(0x81a2a00, 0x185af540, 0x0)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:335 +0x24 fp=0x1851cf4c sp=0x1851cf34
runtime/pprof_test.TestTraceStressStartStop(0x193602a0)
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:361 +0x2d9 fp=0x1851cfbc sp=0x1851cf4c
testing.tRunner(0x193602a0, 0x82f43f0)
    /tmp/buildlet-scatch821635628/go/src/testing/testing.go:452 +0xa6 fp=0x1851cfe8 sp=0x1851cfbc
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851cfec sp=0x1851cfe8
created by testing.RunTests
    /tmp/buildlet-scatch821635628/go/src/testing/testing.go:560 +0x84e

goroutine 7 [runnable]:
runtime.gopark(0x825db84, 0x82f5940, 0x8215fe8, 0x12, 0x18520e14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x18520fbc sp=0x18520fa4
runtime.goparkunlock(0x82f5940, 0x8215fe8, 0x12, 0x14, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x18520fd8 sp=0x18520fbc
runtime.backgroundgc()
    /tmp/buildlet-scatch821635628/go/src/runtime/mgc.go:300 +0x8a fp=0x18520ff0 sp=0x18520fd8
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x18520ff4 sp=0x18520ff0
created by runtime.startGC
    /tmp/buildlet-scatch821635628/go/src/runtime/mgc.go:267 +0x10d

goroutine 41 [select (no cases)]:
runtime.gopark(0x0, 0x0, 0x821a388, 0x11, 0x82f5a10, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1851b7d0 sp=0x1851b7b8
runtime.block()
    /tmp/buildlet-scatch821635628/go/src/runtime/select.go:205 +0x4e fp=0x1851b7ec sp=0x1851b7d0
runtime/pprof_test.TestTraceSymbolize.func1()
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_stack_test.go:38 +0x1e fp=0x1851b7f0 sp=0x1851b7ec
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851b7f4 sp=0x1851b7f0
created by runtime/pprof_test.TestTraceSymbolize
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_stack_test.go:39 +0x17c

goroutine 42 [chan send (nil chan)]:
runtime.gopark(0x0, 0x0, 0x821c428, 0x14, 0x2bb77910, 0x2)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x18521f50 sp=0x18521f38
runtime.chansend(0x81a2a80, 0x0, 0x18521fe8, 0x2bb82c01, 0x80bf27e, 0xccbe11a8)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:116 +0x6b fp=0x18521fc0 sp=0x18521f50
runtime.chansend1(0x81a2a80, 0x0, 0x18521fe8)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:92 +0x38 fp=0x18521fdc sp=0x18521fc0
runtime/pprof_test.TestTraceSymbolize.func2()
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_stack_test.go:42 +0x3e fp=0x18521ff0 sp=0x18521fdc
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x18521ff4 sp=0x18521ff0
created by runtime/pprof_test.TestTraceSymbolize
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_stack_test.go:43 +0x191

goroutine 43 [chan receive (nil chan)]:
runtime.gopark(0x0, 0x0, 0x821c408, 0x17, 0x10, 0x2)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x18520760 sp=0x18520748
runtime.chanrecv(0x81a2a80, 0x0, 0x0, 0x1, 0x0)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:360 +0x6d fp=0x185207c8 sp=0x18520760
runtime.chanrecv1(0x81a2a80, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:335 +0x24 fp=0x185207e0 sp=0x185207c8
runtime/pprof_test.TestTraceSymbolize.func3()
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_stack_test.go:46 +0x36 fp=0x185207f0 sp=0x185207e0
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x185207f4 sp=0x185207f0
created by runtime/pprof_test.TestTraceSymbolize
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_stack_test.go:47 +0x1a6

goroutine 63 [runnable]:
runtime.shouldtriggergc(0x18590000)
    /tmp/buildlet-scatch821635628/go/src/runtime/mgc.go:191 fp=0x1eee5ea0 sp=0x1eee5e9c
runtime.mallocgc(0x100000, 0x81a8440, 0x1, 0x19466000)
    /tmp/buildlet-scatch821635628/go/src/runtime/malloc.go:680 +0x3aa fp=0x1eee5f08 sp=0x1eee5ea0
runtime.newarray(0x81a8440, 0x100000, 0x19466000)
    /tmp/buildlet-scatch821635628/go/src/runtime/malloc.go:736 +0xb0 fp=0x1eee5f28 sp=0x1eee5f08
runtime.makeslice(0x81a2740, 0x100000, 0x0, 0x100000, 0x0, 0x0, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/runtime/slice.go:32 +0x157 fp=0x1eee5f54 sp=0x1eee5f28
runtime/pprof_test.TestTraceStressStartStop.func1(0x185af540, 0x193602a0)
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:277 +0x274 fp=0x1eee5fe8 sp=0x1eee5f54
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1eee5fec sp=0x1eee5fe8
created by runtime/pprof_test.TestTraceStressStartStop
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:348 +0x9f

goroutine 67 [chan receive]:
runtime.gopark(0x825db84, 0x185141b0, 0x8210988, 0xc, 0x17, 0x3)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1eee173c sp=0x1eee1724
runtime.goparkunlock(0x185141b0, 0x8210988, 0xc, 0x17, 0x3)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:187 +0x52 fp=0x1eee1758 sp=0x1eee173c
runtime.chanrecv(0x81a2a00, 0x18514180, 0x0, 0x1, 0x0)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:434 +0x3ce fp=0x1eee17c0 sp=0x1eee1758
runtime.chanrecv1(0x81a2a00, 0x18514180, 0x0)
    /tmp/buildlet-scatch821635628/go/src/runtime/chan.go:335 +0x24 fp=0x1eee17d8 sp=0x1eee17c0
runtime/pprof_test.TestTraceStressStartStop.func1.2(0x18514180, 0x19362020)
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:241 +0x38 fp=0x1eee17e8 sp=0x1eee17d8
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1eee17ec sp=0x1eee17e8
created by runtime/pprof_test.TestTraceStressStartStop.func1
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:243 +0xbd

goroutine 65 [runnable, locked to thread]:
runtime.Gosched()
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:162 +0x10 fp=0x1851d7d0 sp=0x1851d7c8
runtime/pprof_test.TestTraceStressStartStop.func1.5(0x18514180)
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:269 +0xb4 fp=0x1851d7e8 sp=0x1851d7d0
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1851d7ec sp=0x1851d7e8
created by runtime/pprof_test.TestTraceStressStartStop.func1
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:272 +0x236

goroutine 68 [syscall]:
syscall.Syscall(0x3, 0x3, 0x1eee1fcf, 0x1, 0x0, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/syscall/asm_linux_386.s:16 +0x5 fp=0x1eee1f24 sp=0x1eee1f20
syscall.read(0x3, 0x1eee1fcf, 0x1, 0x1, 0x0, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/syscall/zsyscall_linux_386.go:792 +0x56 fp=0x1eee1f44 sp=0x1eee1f24
syscall.Read(0x3, 0x1eee1fcf, 0x1, 0x1, 0x0, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/syscall/syscall_unix.go:160 +0x4c fp=0x1eee1f64 sp=0x1eee1f44
os.(*File).read(0x19364000, 0x1eee1fcf, 0x1, 0x1, 0x0, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/os/file_unix.go:211 +0x51 fp=0x1eee1f84 sp=0x1eee1f64
os.(*File).Read(0x19364000, 0x1eee1fcf, 0x1, 0x1, 0x0, 0x0, 0x0)
    /tmp/buildlet-scatch821635628/go/src/os/file.go:95 +0x72 fp=0x1eee1fb0 sp=0x1eee1f84
runtime/pprof_test.TestTraceStressStartStop.func1.4(0x19364000, 0x18514180, 0x19362020)
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:256 +0x5a fp=0x1eee1fe0 sp=0x1eee1fb0
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1eee1fe4 sp=0x1eee1fe0
created by runtime/pprof_test.TestTraceStressStartStop.func1
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:259 +0x205

goroutine 98 [select (no cases)]:
runtime.gopark(0x0, 0x0, 0x821a388, 0x11, 0x806c810, 0x1)
    /tmp/buildlet-scatch821635628/go/src/runtime/proc.go:181 +0x135 fp=0x1eee37d0 sp=0x1eee37b8
runtime.block()
    /tmp/buildlet-scatch821635628/go/src/runtime/select.go:205 +0x4e fp=0x1eee37ec sp=0x1eee37d0
runtime/pprof_test.TestTraceStress.func9()
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:205 +0x23 fp=0x1eee37f0 sp=0x1eee37ec
runtime.goexit()
    /tmp/buildlet-scatch821635628/go/src/runtime/asm_386.s:1637 +0x1 fp=0x1eee37f4 sp=0x1eee37f0
created by runtime/pprof_test.TestTraceStress
    /tmp/buildlet-scatch821635628/go/src/runtime/pprof/trace_test.go:206 +0x81d
FAIL    runtime/pprof   7.822s