runtime/pprof: unexpected signal during runtime execution on windows-386-gce

[alexbrainman]

I cannot reproduce it myself, but from windows-386-gce builder http://build.golang.org/log/e3bf7d994667518abb7f2a2f0064257d8c373927 while building 56a7c5b

fatal error: unexpected signal during runtime execution
[signal 0xc0000005 code=0x0 addr=0x2140c00 pc=0x40d8c1]

runtime stack:
runtime.throw(0x5ff288, 0x2a)
    C:/workdir/go/src/runtime/panic.go:543 +0x7f
runtime.sigpanic()
    C:/workdir/go/src/runtime/signal_windows.go:157 +0x5c
runtime.gcmarkwb_m(0x3280000c, 0x32800218)
    C:/workdir/go/src/runtime/mbarrier.go:73 +0xb1
runtime.writebarrierptr_nostore1.func1()
    C:/workdir/go/src/runtime/mbarrier.go:107 +0x117
runtime.systemstack(0x32a7fdfc)
    C:/workdir/go/src/runtime/asm_386.s:283 +0x81
runtime.writebarrierptr_nostore1(0x3280000c, 0x32800218)
    C:/workdir/go/src/runtime/mbarrier.go:108 +0x56
runtime.writebarrierptr(0x3280000c, 0x32800218)
    C:/workdir/go/src/runtime/mbarrier.go:131 +0x7f
runtime.writebarrierslice(0x3280000c, 0x32800218, 0x6933, 0xfde8)
    C:/workdir/go/src/runtime/mbarrier.go:207 +0x1e
runtime.traceEvent(0x15, 0x0, 0x32a7fee4, 0x1, 0x1)
    C:/workdir/go/src/runtime/trace.go:502 +0x5b2
runtime.traceGoUnpark(0x12215080, 0x0)
    C:/workdir/go/src/runtime/trace.go:793 +0x75
runtime.findrunnable(0x12212a00)
    C:/workdir/go/src/runtime/proc1.go:1345 +0x251
runtime.schedule()
    C:/workdir/go/src/runtime/proc1.go:1515 +0x1dd
runtime.park_m(0x12215080)
    C:/workdir/go/src/runtime/proc1.go:1574 +0x161
runtime.mcall(0x0)
    C:/workdir/go/src/runtime/asm_386.s:210 +0x47

goroutine 1 [chan receive]:
testing.RunTests(0x620844, 0x6b83e0, 0xe, 0xe, 0x12246001)
    C:/workdir/go/src/testing/testing.go:561 +0x884
testing.(*M).Run(0x12206360, 0x6cf540)
    C:/workdir/go/src/testing/testing.go:490 +0x6b
main.main()
    runtime/pprof/_test/_testmain.go:82 +0x177

goroutine 58 [runnable]:
runtime/pprof_test.TestTraceStress(0x18a9dd40)
    C:/workdir/go/src/runtime/pprof/trace_test.go:149 +0x3af
testing.tRunner(0x18a9dd40, 0x6b8464)
    C:/workdir/go/src/testing/testing.go:452 +0xa6
created by testing.RunTests
    C:/workdir/go/src/testing/testing.go:560 +0x852

goroutine 41 [select (no cases)]:
runtime/pprof_test.TestTraceSymbolize.func1()
    C:/workdir/go/src/runtime/pprof/trace_stack_test.go:38 +0x1e
created by runtime/pprof_test.TestTraceSymbolize
    C:/workdir/go/src/runtime/pprof/trace_stack_test.go:39 +0x178

goroutine 60 [syscall, locked to thread]:
syscall.Syscall6(0x77433e93, 0x5, 0x194, 0x1268cfcf, 0x1, 0x1268cf38, 0x0, 0x0, 0x40bbd6, 0x6be720, ...)
    C:/workdir/go/src/runtime/syscall_windows.go:139 +0x4b
syscall.ReadFile(0x194, 0x1268cfcf, 0x1, 0x1, 0x1268cf38, 0x0, 0x0, 0x0)
    C:/workdir/go/src/syscall/zsyscall_windows.go:283 +0xa0
syscall.Read(0x194, 0x1268cfcf, 0x1, 0x1, 0xf69, 0x0, 0x0)
    C:/workdir/go/src/syscall/syscall_windows.go:286 +0x64
os.(*File).read(0x1221e658, 0x1268cfcf, 0x1, 0x1, 0x0, 0x0, 0x0)
    C:/workdir/go/src/os/file_windows.go:300 +0x106
os.(*File).Read(0x1221e658, 0x1268cfcf, 0x1, 0x1, 0x0, 0x0, 0x0)
    C:/workdir/go/src/os/file.go:95 +0x72
runtime/pprof_test.TestTraceStress.func3(0x1221e658, 0x126a7940, 0x1228c9a0)
    C:/workdir/go/src/runtime/pprof/trace_test.go:120 +0x5b
created by runtime/pprof_test.TestTraceStress
    C:/workdir/go/src/runtime/pprof/trace_test.go:123 +0x1ff

goroutine 42 [chan send (nil chan)]:
runtime/pprof_test.TestTraceSymbolize.func2()
    C:/workdir/go/src/runtime/pprof/trace_stack_test.go:42 +0x3e
created by runtime/pprof_test.TestTraceSymbolize
    C:/workdir/go/src/runtime/pprof/trace_stack_test.go:43 +0x18d

goroutine 43 [chan receive (nil chan)]:
runtime/pprof_test.TestTraceSymbolize.func3()
    C:/workdir/go/src/runtime/pprof/trace_stack_test.go:46 +0x36
created by runtime/pprof_test.TestTraceSymbolize
    C:/workdir/go/src/runtime/pprof/trace_stack_test.go:47 +0x1a2

goroutine 62 [runnable, locked to thread]:
runtime.Gosched()
    C:/workdir/go/src/runtime/proc.go:166 +0x10
runtime/pprof_test.TestTraceStress.func4(0x126a7940)
    C:/workdir/go/src/runtime/pprof/trace_test.go:141 +0xb4
created by runtime/pprof_test.TestTraceStress
    C:/workdir/go/src/runtime/pprof/trace_test.go:144 +0x371

goroutine 59 [chan receive]:
runtime/pprof_test.TestTraceStress.func1(0x126a7940, 0x1228c9a0)
    C:/workdir/go/src/runtime/pprof/trace_test.go:104 +0x38
created by runtime/pprof_test.TestTraceStress
    C:/workdir/go/src/runtime/pprof/trace_test.go:106 +0xa3

goroutine 61 [trace reader (blocked)]:
runtime.ReadTrace(0x0, 0x0, 0x0)
    C:/workdir/go/src/runtime/trace.go:313 +0x1d9
runtime/pprof.StartTrace.func1(0x3b0c58, 0x18a9dda0)
    C:/workdir/go/src/runtime/pprof/pprof.go:629 +0x21
created by runtime/pprof.StartTrace
    C:/workdir/go/src/runtime/pprof/pprof.go:635 +0x70
FAIL    runtime/pprof   8.670s

I also have couple of questions about the stack trace:

• It looks like our exception handler got fired because of EXCEPTION_ACCESS_VIOLATION (see signal 0xc0000005). The source code line where it happened must be mbarrier.go:73 - it is right before signal_windows.go:157 (runtime.sigpanic). Looking at that line: "if ptr != 0 && inheap(ptr) {", I don't see how it is possible for EXCEPTION_ACCESS_VIOLATION to be raised here. Can someone explain?
• Also "runtime stack:" starts with runtime.mcall. But why? Who called it? Looking at remaining goroutine stacks, I see "goroutine 58 [runnable]" allocating memory at trace_test.go:149 with "_ = make([]byte, 1<<20)". But how did we get from allocating memory into runtime.mcall?

I suspect there is missing information here. Is it OK for it to be missing? How should I debug this crash?

Perhaps I am misreading this altogether.

Alex

[alexbrainman]

My mistake. I missed runtime.Gosched at the top of "goroutine 62 [runnable, locked to thread]". It calls mcall(gosched_m). But I still don't see how exception is possible at mbarrier.go:73.

Another similar crash http://build.golang.org/log/cd25098806926c3c1edd92ca598ab37c7a627e7f from the same builder.

Alex

[alexbrainman]

Another similar failure http://build.golang.org/log/b0f209367c73a2a770df86b7f4549c509f3f6e17

[rsc]

Duplicate of #10212.

[aclements]

Closing as duplicate (though note that I just reopened #10212).