runtime: TestCgoCCodeSIGPROF fails intermittently on darwin/amd64

[YoshikiShibata]

Please answer these questions before submitting your issue. Thanks!

1. What version of Go are you using (go version)?
   I build from the tip source:
   go version devel +883e128 Wed Jul 20 05:08:37 2016 +0000 darwin/amd64
2. What operating system and processor architecture are you using (go env)?
   GOARCH="amd64"
   GOBIN=""
   GOEXE=""
   GOHOSTARCH="amd64"
   GOHOSTOS="darwin"
   GOOS="darwin"
   GOPATH="/Users/yoshiki/gocode:/Users/yoshiki/exercises/gpl"
   GORACE=""
   GOROOT="/Users/yoshiki/tools/go"
   GOTOOLDIR="/Users/yoshiki/tools/go/pkg/tool/darwin_amd64"
   CC="clang"
   GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/pb/c7_4_d355ng5zfm4r_jg2gg00000gn/T/go-build655954293=/tmp/go-build -gno-record-gcc-switches -fno-common"
   CXX="clang++"
   CGO_ENABLED="1"
3. What did you do?
   just rebuild with all.bash
4. What did you expect to see?
   no error
5. What did you see instead?
   Following error does not always happen, but happens sometimes:

GOMAXPROCS=2 runtime -cpu=1,2,4

--- FAIL: TestCgoCCodeSIGPROF (0.72s)
crash_test.go:105: testprogcgo CgoCCodeSIGPROF exit status: exit status 2
crash_cgo_test.go:213: expected "OK\n" got runtime: invalid pc-encoded table f=runtime.sigtramp pc=0x405e52d targetpc=0x405e52d tab=[0/0]0x0
value=0 until pc=0x405e504
value=40 until pc=0x405e52d
fatal error: invalid runtime symbol table

    goroutine 0 [idle]:
    invalid spdelta runtime.sigtramp 0x405e500 0x405e52d 0x32b2a -1
    runtime.throw(0x40e0c58, 0x1c)
        /Users/yoshiki/tools/go/src/runtime/panic.go:566 +0x95
    runtime.pcvalue(0x411f1d0, 0x32b2a, 0x405e52d, 0xc420031480, 0x1, 0x98)
        /Users/yoshiki/tools/go/src/runtime/symtab.go:472 +0x4cd
    runtime.funcspdelta(0x411f1d0, 0x405e52d, 0xc420031480, 0x98)
        /Users/yoshiki/tools/go/src/runtime/symtab.go:511 +0x4f
    runtime.gentraceback(0x405e465, 0x7000000807b0, 0x0, 0xc4200004e0, 0x0, 0xc4200316b0, 0x40, 0x0, 0x0, 0x6, ...)
        /Users/yoshiki/tools/go/src/runtime/traceback.go:264 +0x163b
    runtime.sigprof(0x405e465, 0x7000000807b0, 0x0, 0xc4200004e0, 0xc420028000)
        /Users/yoshiki/tools/go/src/runtime/proc.go:3116 +0x17e
    runtime.sighandler(0xc40000001b, 0xc420031e80, 0xc420031ee8, 0xc4200004e0)
        /Users/yoshiki/tools/go/src/runtime/signal_amd64x.go:49 +0xb3
    runtime.sigtrampgo(0x4041820, 0x1b0000001e, 0xc420031e80, 0xc420031ee8)
        /Users/yoshiki/tools/go/src/runtime/signal_darwin.go:91 +0x281
    invalid spdelta runtime.sigtramp 0x405e500 0x405e52d 0x32b2a -1
    runtime.sigtramp(0x1b0000001e00, 0xc420031e8000, 0xc420031ee800, 0x7000000807f800, 0x0, 0x0, 0x0, 0x0, 0x1490000008500, 0x1089ea00002, ...)
        /Users/yoshiki/tools/go/src/runtime/sys_darwin_amd64.s:246 +0x2d

    goroutine 17 [syscall, locked to thread]:
    runtime.goexit()
        /Users/yoshiki/tools/go/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc420036fb8 sp=0xc420036fb0

    goroutine 1 [chan receive]:
    main.CgoCCodeSIGPROF()
        /Users/yoshiki/tools/go/src/runtime/testdata/testprogcgo/aprof.go:49 +0xf3
    main.main()
        /Users/yoshiki/tools/go/src/runtime/testdata/testprogcgo/main.go:34 +0x1f1

    goroutine 19 [syscall]:
    os/signal.signal_recv(0x0)
        /Users/yoshiki/tools/go/src/runtime/sigqueue.go:116 +0x157
    os/signal.loop()
        /Users/yoshiki/tools/go/src/os/signal/signal_unix.go:22 +0x22
    created by os/signal.init.1
        /Users/yoshiki/tools/go/src/os/signal/signal_unix.go:28 +0x41

    goroutine 20 [runnable]:
    main._Cfunc_GoNop()
        _/Users/yoshiki/tools/go/src/runtime/testdata/testprogcgo/_obj/_cgo_gotypes.go:118
    main.CgoCCodeSIGPROF.func1(0xc42005c060)
        /Users/yoshiki/tools/go/src/runtime/testdata/testprogcgo/aprof.go:41 +0xaa
    created by main.CgoCCodeSIGPROF
        /Users/yoshiki/tools/go/src/runtime/testdata/testprogcgo/aprof.go:44 +0x61

    goroutine 21 [syscall]:
    runtime.CPUProfile(0x0, 0x0, 0x0)
        /Users/yoshiki/tools/go/src/runtime/cpuprof.go:447 +0x2d
    runtime/pprof.profileWriter(0x4145240, 0xc420084000)
        /Users/yoshiki/tools/go/src/runtime/pprof/pprof.go:615 +0x26
    created by runtime/pprof.StartCPUProfile
        /Users/yoshiki/tools/go/src/runtime/pprof/pprof.go:609 +0x122

    goroutine 34 [syscall, locked to thread]:
    runtime.goexit()
        /Users/yoshiki/tools/go/src/runtime/asm_amd64.s:2086 +0x1

FAIL
FAIL runtime 61.228s
2016/07/20 21:09:05 Failed: exit status 1

[ianlancetaylor]

CC @aclements

[josharian]

Possibly related, I just saw a TestCgoCallbackGC failure both locally (darwin/amd64) and also at https://storage.googleapis.com/go-build-log/1e5e50ed/freebsd-amd64-gce101_6ab63a8e.log. I'm running a stress test to see if I can reproduce again, and if so, with what frequency.

[ianlancetaylor]

If I'm reading this line correctly

invalid spdelta runtime.sigtramp 0x405e500 0x405e52d 0x32b2a -1

this means that funcspdelta was called with targetpc pointing just after the call to runtime·sigtrampgo at the end of runtime·sigtramp in runtime/sys_darwin_amd64.s.

That suggests that the fix is https://golang.org/cl/25104. Could you try that? Thanks.

[josharian]

I had 6 failures on 1956 runs. Will try the CL now and report back...

[gopherbot]

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

[josharian]

I just got a failure after 564 runs with that CL patched in.

--- FAIL: TestCgoExternalThreadSignal (60.03s)
    crash_test.go:105: testprogcgo CgoExternalThreadSignal exit status: exit status 2
    crash_cgo_test.go:116: expected "OK\n", but got:
        SIGQUIT: quit
        PC=0x407475e m=0

        goroutine 1 [syscall]:
        syscall.Syscall6(0xad, 0x1, 0x564e, 0xc4200a6080, 0x24, 0x0, 0x0, 0x40c46a0, 0xc420059bb0, 0x40371de)
            /Users/josh/go/tip/src/syscall/asm_darwin_amd64.s:41 +0x5 fp=0xc420059b28 sp=0xc420059b20
        os.(*Process).blockUntilWaitable(0xc42007a300, 0x40e9c98, 0xc42009c000, 0xc42008a100)
            /Users/josh/go/tip/src/os/wait_waitid.go:28 +0xbc fp=0xc420059bc0 sp=0xc420059b28
        os.(*Process).wait(0xc42007a300, 0x0, 0x4015c6e, 0xc420088040)
            /Users/josh/go/tip/src/os/exec_unix.go:22 +0xab fp=0xc420059c50 sp=0xc420059bc0
        os.(*Process).Wait(0xc42007a300, 0xc420059cb8, 0x0, 0x0)
            /Users/josh/go/tip/src/os/doc.go:49 +0x2b fp=0xc420059c80 sp=0xc420059c50
        os/exec.(*Cmd).Wait(0xc42009c000, 0x0, 0x0)
            /Users/josh/go/tip/src/os/exec/exec.go:434 +0x6d fp=0xc420059d10 sp=0xc420059c80
        os/exec.(*Cmd).Run(0xc42009c000, 0xc42009e000, 0x3)
            /Users/josh/go/tip/src/os/exec/exec.go:279 +0x48 fp=0xc420059d38 sp=0xc420059d10
        os/exec.(*Cmd).CombinedOutput(0xc42009c000, 0x52, 0xc420059e50, 0x2, 0x2, 0xc42009c000)
            /Users/josh/go/tip/src/os/exec/exec.go:494 +0x13b fp=0xc420059d78 sp=0xc420059d38
        main.CgoExternalThreadSignal()
            /Users/josh/go/tip/src/runtime/testdata/testprogcgo/threadprof.go:85 +0xe3 fp=0xc420059ea0 sp=0xc420059d78
        main.main()
            /Users/josh/go/tip/src/runtime/testdata/testprogcgo/main.go:34 +0x1f1 fp=0xc420059f48 sp=0xc420059ea0
        runtime.main()
            /Users/josh/go/tip/src/runtime/proc.go:183 +0x1f4 fp=0xc420059fa0 sp=0xc420059f48
        runtime.goexit()
            /Users/josh/go/tip/src/runtime/asm_amd64.s:2086 +0x1 fp=0xc420059fa8 sp=0xc420059fa0

        goroutine 17 [syscall, locked to thread]:
        runtime.goexit()
            /Users/josh/go/tip/src/runtime/asm_amd64.s:2086 +0x1

        goroutine 19 [syscall]:
        os/signal.signal_recv(0x0)
            /Users/josh/go/tip/src/runtime/sigqueue.go:116 +0x157

The previous 6 failures were 1 TestCgoCCodeSIGPROF, 5 TestCgoExternalThreadSignal.

I'm going to restart with just the TestCgoCCodeSIGPROF running.

[josharian]

3668 runs, no TestCgoCCodeSIGPROF failures. Switching back to all Cgo tests with a 10m instead of 1m timeout for TestCgoExternalThreadSignal, just to make sure the SIGPROF failures didn't require running all Cgo tests to trigger.

[ianlancetaylor]

The TestCgoExternalThreadSignal failure is a different problem. It's #14809.

[ianlancetaylor]

By the way, it's rather unlikely that an extended timeout for TestCgoExternalThreadSIgnal will help. The program in question should crash immediately. If it doesn't crash immediately, it should exit in five seconds. The fact that the test hangs for a full minute means that something has gone wrong with the exiting process somehow. I very much doubt that extending the timeout is going to help.