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.

Sign up for GitHub

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

Jump to bottom

runtime: concurrent GC sweep broke runtime tests on Solaris #7511

Closed
4ad opened this issue Mar 11, 2014 · 43 comments
Closed

runtime: concurrent GC sweep broke runtime tests on Solaris #7511

4ad opened this issue Mar 11, 2014 · 43 comments
Labels
FrozenDueToAge

Comments

@4ad
Copy link
Member

4ad commented Mar 11, 2014 

Runtime tests will deadlock in various places, usually in
TestLockedDeadlock2:
    
    : oos:src; GOMAXPROCS=2 go test -v -short -timeout=60s -cpu=1,2,4 runtime
    === RUN TestSideEffectOrder
    --- PASS: TestSideEffectOrder (0.00 seconds)
    === RUN TestAppendOverlap
    --- PASS: TestAppendOverlap (0.00 seconds)
    === RUN TestChan
    --- PASS: TestChan (0.99 seconds)
    === RUN TestSelfSelect
    --- PASS: TestSelfSelect (0.01 seconds)
    === RUN TestSelectStress
    --- PASS: TestSelectStress (0.49 seconds)
    === RUN TestChanSendInterface
    --- PASS: TestChanSendInterface (0.00 seconds)
    === RUN TestPseudoRandomSend
    --- PASS: TestPseudoRandomSend (0.00 seconds)
    === RUN TestMultiConsumer
    --- PASS: TestMultiConsumer (0.17 seconds)
    === RUN TestCrashHandler
    --- PASS: TestCrashHandler (0.57 seconds)
    === RUN TestSimpleDeadlock
    --- PASS: TestSimpleDeadlock (0.25 seconds)
    === RUN TestInitDeadlock
    --- PASS: TestInitDeadlock (0.23 seconds)
    === RUN TestLockedDeadlock
    --- PASS: TestLockedDeadlock (0.24 seconds)
    === RUN TestLockedDeadlock2
    --- PASS: TestLockedDeadlock2 (0.34 seconds)
    === RUN TestGoexitDeadlock
    --- PASS: TestGoexitDeadlock (0.20 seconds)
    === RUN TestStackOverflow
    --- PASS: TestStackOverflow (0.66 seconds)
    === RUN TestThreadExhaustion
    --- PASS: TestThreadExhaustion (0.64 seconds)
    === RUN TestGcSys
    --- PASS: TestGcSys (0.58 seconds)
    === RUN TestGcDeepNesting
    --- PASS: TestGcDeepNesting (0.00 seconds)
        gc_test.go:77: 0xc20818a000
    === RUN TestGcHashmapIndirection
    --- PASS: TestGcHashmapIndirection (0.18 seconds)
    === RUN TestGcArraySlice
    --- PASS: TestGcArraySlice (0.01 seconds)
    === RUN TestGcRescan
    --- PASS: TestGcRescan (0.01 seconds)
    === RUN TestSmhasherSanity
    --- PASS: TestSmhasherSanity (0.23 seconds)
    === RUN TestSmhasherAppendedZeros
    --- PASS: TestSmhasherAppendedZeros (0.00 seconds)
    === RUN TestSmhasherSmallKeys
    --- PASS: TestSmhasherSmallKeys (0.03 seconds)
    === RUN TestSmhasherZeros
    --- PASS: TestSmhasherZeros (0.00 seconds)
    === RUN TestSmhasherTwoNonzero
    --- SKIP: TestSmhasherTwoNonzero (0.00 seconds)
        hash_test.go:130: Skipping in short mode
    === RUN TestSmhasherCyclic
    --- SKIP: TestSmhasherCyclic (0.00 seconds)
        hash_test.go:172: Skipping in short mode
    === RUN TestSmhasherSparse
    --- SKIP: TestSmhasherSparse (0.00 seconds)
        hash_test.go:201: Skipping in short mode
    === RUN TestSmhasherPermutation
    --- SKIP: TestSmhasherPermutation (0.00 seconds)
        hash_test.go:236: Skipping in short mode
    === RUN TestSmhasherAvalanche
    --- SKIP: TestSmhasherAvalanche (0.00 seconds)
        hash_test.go:350: fallback hash not good enough for this test
    === RUN TestSmhasherWindowed
    --- SKIP: TestSmhasherWindowed (0.00 seconds)
        hash_test.go:426: Skipping in short mode
    === RUN TestSmhasherText
    --- SKIP: TestSmhasherText (0.00 seconds)
        hash_test.go:448: Skipping in short mode
    === RUN TestSmhasherSeed
    --- PASS: TestSmhasherSeed (0.04 seconds)
    === RUN TestLFStack
    --- PASS: TestLFStack (0.00 seconds)
    === RUN TestLFStackStress
    --- PASS: TestLFStackStress (0.01 seconds)
    === RUN TestMemStats
    --- PASS: TestMemStats (0.00 seconds)
    === RUN TestNegativeZero
    --- PASS: TestNegativeZero (0.00 seconds)
    === RUN TestNan
    --- PASS: TestNan (0.00 seconds)
    === RUN TestAlias
    --- PASS: TestAlias (0.00 seconds)
    === RUN TestGrowWithNaN
    --- PASS: TestGrowWithNaN (0.00 seconds)
    === RUN TestGrowWithNegativeZero
    --- PASS: TestGrowWithNegativeZero (0.00 seconds)
    === RUN TestIterGrowAndDelete
    --- PASS: TestIterGrowAndDelete (0.00 seconds)
    === RUN TestIterGrowWithGC
    --- PASS: TestIterGrowWithGC (0.00 seconds)
    === RUN TestConcurrentReadsAfterGrowth
    --- PASS: TestConcurrentReadsAfterGrowth (0.44 seconds)
    === RUN TestConcurrentReadsAfterGrowthReflect
    --- PASS: TestConcurrentReadsAfterGrowthReflect (2.66 seconds)
    === RUN TestBigItems
    --- PASS: TestBigItems (0.01 seconds)
    === RUN TestEmptyKeyAndValue
    --- PASS: TestEmptyKeyAndValue (0.00 seconds)
    === RUN TestSingleBucketMapStringKeys_DupLen
    --- PASS: TestSingleBucketMapStringKeys_DupLen (0.00 seconds)
    === RUN TestSingleBucketMapStringKeys_NoDupLen
    --- PASS: TestSingleBucketMapStringKeys_NoDupLen (0.00 seconds)
    === RUN TestMapNanGrowIterator
    --- PASS: TestMapNanGrowIterator (0.00 seconds)
    === RUN TestMapIterOrder
    --- PASS: TestMapIterOrder (0.00 seconds)
    === RUN TestMemmove
    --- PASS: TestMemmove (0.60 seconds)
    === RUN TestMemmoveAlias
    --- PASS: TestMemmoveAlias (0.45 seconds)
    === RUN TestMemclr
    --- PASS: TestMemclr (0.01 seconds)
    === RUN TestFinalizerType
    --- PASS: TestFinalizerType (0.01 seconds)
    === RUN TestFinalizerInterfaceBig
    --- PASS: TestFinalizerInterfaceBig (0.00 seconds)
    === RUN TestFinalizerZeroSizedStruct
    --- PASS: TestFinalizerZeroSizedStruct (0.00 seconds)
    === RUN TestParFor
    --- PASS: TestParFor (0.00 seconds)
    === RUN TestParFor2
    --- PASS: TestParFor2 (0.00 seconds)
    === RUN TestParForSetup
    --- PASS: TestParForSetup (0.00 seconds)
    === RUN TestParForParallel
    --- PASS: TestParForParallel (0.03 seconds)
    === RUN TestStopTheWorldDeadlock
    --- SKIP: TestStopTheWorldDeadlock (0.00 seconds)
        proc_test.go:28: skipping during short test
    === RUN TestYieldProgress
    --- PASS: TestYieldProgress (0.01 seconds)
    === RUN TestYieldLockedProgress
    --- PASS: TestYieldLockedProgress (0.01 seconds)
    === RUN TestYieldLocked
    --- PASS: TestYieldLocked (0.10 seconds)
    === RUN TestGoroutineParallelism
    --- PASS: TestGoroutineParallelism (2.08 seconds)
    === RUN TestBlockLocked
    --- PASS: TestBlockLocked (0.00 seconds)
    === RUN TestTimerFairness
    --- PASS: TestTimerFairness (0.03 seconds)
    === RUN TestTimerFairness2
    --- PASS: TestTimerFairness2 (0.02 seconds)
    === RUN TestPreemption
    --- PASS: TestPreemption (0.04 seconds)
    === RUN TestPreemptionGC
    --- PASS: TestPreemptionGC (0.22 seconds)
    === RUN TestGCFairness
    --- PASS: TestGCFairness (0.74 seconds)
    === RUN TestPreemptSplitBig
    --- SKIP: TestPreemptSplitBig (0.00 seconds)
        proc_test.go:299: skipping in -short mode
    === RUN TestSchedLocalQueue
    --- PASS: TestSchedLocalQueue (0.00 seconds)
    === RUN TestSchedLocalQueueSteal
    --- PASS: TestSchedLocalQueueSteal (0.00 seconds)
    === RUN TestRuntimeGogoBytes
    --- PASS: TestRuntimeGogoBytes (0.23 seconds)
    === RUN TestStopCPUProfilingWithProfilerOff
    --- PASS: TestStopCPUProfilingWithProfilerOff (0.00 seconds)
    === RUN TestFloat64
    --- PASS: TestFloat64 (0.12 seconds)
    === RUN TestStackSplit
    --- PASS: TestStackSplit (0.02 seconds)
    === RUN TestStackMem
    --- PASS: TestStackMem (0.00 seconds)
    === RUN TestCaller
    --- PASS: TestCaller (0.01 seconds)
    === RUN TestSideEffectOrder-2
    --- PASS: TestSideEffectOrder-2 (0.00 seconds)
    === RUN TestAppendOverlap-2
    --- PASS: TestAppendOverlap-2 (0.00 seconds)
    === RUN TestChan-2
    --- PASS: TestChan-2 (0.76 seconds)
    === RUN TestSelfSelect-2
    --- PASS: TestSelfSelect-2 (0.01 seconds)
    === RUN TestSelectStress-2
    --- PASS: TestSelectStress-2 (0.77 seconds)
    === RUN TestChanSendInterface-2
    --- PASS: TestChanSendInterface-2 (0.00 seconds)
    === RUN TestPseudoRandomSend-2
    --- PASS: TestPseudoRandomSend-2 (0.00 seconds)
    === RUN TestMultiConsumer-2
    --- PASS: TestMultiConsumer-2 (0.47 seconds)
    === RUN TestCrashHandler-2
    --- PASS: TestCrashHandler-2 (0.56 seconds)
    === RUN TestSimpleDeadlock-2
    --- PASS: TestSimpleDeadlock-2 (0.26 seconds)
    === RUN TestInitDeadlock-2
    --- PASS: TestInitDeadlock-2 (0.21 seconds)
    === RUN TestLockedDeadlock-2
    --- PASS: TestLockedDeadlock-2 (0.23 seconds)
    === RUN TestLockedDeadlock2-2
    --- PASS: TestLockedDeadlock2-2 (0.33 seconds)
    === RUN TestGoexitDeadlock-2
    --- PASS: TestGoexitDeadlock-2 (0.26 seconds)
    === RUN TestStackOverflow-2
    --- PASS: TestStackOverflow-2 (0.67 seconds)
    === RUN TestThreadExhaustion-2
    --- PASS: TestThreadExhaustion-2 (0.61 seconds)
    === RUN TestGcSys-2
    --- PASS: TestGcSys-2 (0.60 seconds)
    === RUN TestGcDeepNesting-2
    --- PASS: TestGcDeepNesting-2 (0.00 seconds)
        gc_test.go:77: 0xc208efa000
    === RUN TestGcHashmapIndirection-2
    --- PASS: TestGcHashmapIndirection-2 (0.43 seconds)
    === RUN TestGcArraySlice-2
    --- PASS: TestGcArraySlice-2 (0.03 seconds)
    === RUN TestGcRescan-2
    --- PASS: TestGcRescan-2 (0.02 seconds)
    === RUN TestSmhasherSanity-2
    --- PASS: TestSmhasherSanity-2 (0.23 seconds)
    === RUN TestSmhasherAppendedZeros-2
    --- PASS: TestSmhasherAppendedZeros-2 (0.00 seconds)
    === RUN TestSmhasherSmallKeys-2
    --- PASS: TestSmhasherSmallKeys-2 (0.04 seconds)
    === RUN TestSmhasherZeros-2
    --- PASS: TestSmhasherZeros-2 (0.00 seconds)
    === RUN TestSmhasherTwoNonzero-2
    --- SKIP: TestSmhasherTwoNonzero-2 (0.00 seconds)
        hash_test.go:130: Skipping in short mode
    === RUN TestSmhasherCyclic-2
    --- SKIP: TestSmhasherCyclic-2 (0.00 seconds)
        hash_test.go:172: Skipping in short mode
    === RUN TestSmhasherSparse-2
    --- SKIP: TestSmhasherSparse-2 (0.00 seconds)
        hash_test.go:201: Skipping in short mode
    === RUN TestSmhasherPermutation-2
    --- SKIP: TestSmhasherPermutation-2 (0.00 seconds)
        hash_test.go:236: Skipping in short mode
    === RUN TestSmhasherAvalanche-2
    --- SKIP: TestSmhasherAvalanche-2 (0.00 seconds)
        hash_test.go:350: fallback hash not good enough for this test
    === RUN TestSmhasherWindowed-2
    --- SKIP: TestSmhasherWindowed-2 (0.00 seconds)
        hash_test.go:426: Skipping in short mode
    === RUN TestSmhasherText-2
    --- SKIP: TestSmhasherText-2 (0.00 seconds)
        hash_test.go:448: Skipping in short mode
    === RUN TestSmhasherSeed-2
    --- PASS: TestSmhasherSeed-2 (0.04 seconds)
    === RUN TestLFStack-2
    --- PASS: TestLFStack-2 (0.00 seconds)
    === RUN TestLFStackStress-2
    --- PASS: TestLFStackStress-2 (0.03 seconds)
    === RUN TestMemStats-2
    --- PASS: TestMemStats-2 (0.00 seconds)
    === RUN TestNegativeZero-2
    --- PASS: TestNegativeZero-2 (0.00 seconds)
    === RUN TestNan-2
    --- PASS: TestNan-2 (0.00 seconds)
    === RUN TestAlias-2
    --- PASS: TestAlias-2 (0.00 seconds)
    === RUN TestGrowWithNaN-2
    --- PASS: TestGrowWithNaN-2 (0.00 seconds)
    === RUN TestGrowWithNegativeZero-2
    --- PASS: TestGrowWithNegativeZero-2 (0.00 seconds)
    === RUN TestIterGrowAndDelete-2
    --- PASS: TestIterGrowAndDelete-2 (0.00 seconds)
    === RUN TestIterGrowWithGC-2
    --- PASS: TestIterGrowWithGC-2 (0.01 seconds)
    === RUN TestConcurrentReadsAfterGrowth-2
    --- PASS: TestConcurrentReadsAfterGrowth-2 (0.31 seconds)
    === RUN TestConcurrentReadsAfterGrowthReflect-2
    --- PASS: TestConcurrentReadsAfterGrowthReflect-2 (1.61 seconds)
    === RUN TestBigItems-2
    --- PASS: TestBigItems-2 (0.01 seconds)
    === RUN TestEmptyKeyAndValue-2
    --- PASS: TestEmptyKeyAndValue-2 (0.00 seconds)
    === RUN TestSingleBucketMapStringKeys_DupLen-2
    --- PASS: TestSingleBucketMapStringKeys_DupLen-2 (0.00 seconds)
    === RUN TestSingleBucketMapStringKeys_NoDupLen-2
    --- PASS: TestSingleBucketMapStringKeys_NoDupLen-2 (0.00 seconds)
    === RUN TestMapNanGrowIterator-2
    --- PASS: TestMapNanGrowIterator-2 (0.00 seconds)
    === RUN TestMapIterOrder-2
    --- PASS: TestMapIterOrder-2 (0.00 seconds)
    === RUN TestMemmove-2
    --- PASS: TestMemmove-2 (0.60 seconds)
    === RUN TestMemmoveAlias-2
    --- PASS: TestMemmoveAlias-2 (0.46 seconds)
    === RUN TestMemclr-2
    --- PASS: TestMemclr-2 (0.01 seconds)
    === RUN TestFinalizerType-2
    --- PASS: TestFinalizerType-2 (0.04 seconds)
    === RUN TestFinalizerInterfaceBig-2
    --- PASS: TestFinalizerInterfaceBig-2 (0.01 seconds)
    === RUN TestFinalizerZeroSizedStruct-2
    --- PASS: TestFinalizerZeroSizedStruct-2 (0.00 seconds)
    === RUN TestParFor-2
    --- PASS: TestParFor-2 (0.00 seconds)
    === RUN TestParFor2-2
    --- PASS: TestParFor2-2 (0.00 seconds)
    === RUN TestParForSetup-2
    --- PASS: TestParForSetup-2 (0.00 seconds)
    === RUN TestParForParallel-2
    --- PASS: TestParForParallel-2 (0.04 seconds)
    === RUN TestStopTheWorldDeadlock-2
    --- SKIP: TestStopTheWorldDeadlock-2 (0.00 seconds)
        proc_test.go:28: skipping during short test
    === RUN TestYieldProgress-2
    --- PASS: TestYieldProgress-2 (0.01 seconds)
    === RUN TestYieldLockedProgress-2
    --- PASS: TestYieldLockedProgress-2 (0.01 seconds)
    === RUN TestYieldLocked-2
    --- PASS: TestYieldLocked-2 (0.10 seconds)
    === RUN TestGoroutineParallelism-2
    --- PASS: TestGoroutineParallelism-2 (0.89 seconds)
    === RUN TestBlockLocked-2
    --- PASS: TestBlockLocked-2 (0.00 seconds)
    === RUN TestTimerFairness-2
    --- PASS: TestTimerFairness-2 (0.02 seconds)
    === RUN TestTimerFairness2-2
    --- PASS: TestTimerFairness2-2 (0.02 seconds)
    === RUN TestPreemption-2
    --- PASS: TestPreemption-2 (0.00 seconds)
    === RUN TestPreemptionGC-2
    --- PASS: TestPreemptionGC-2 (0.44 seconds)
    === RUN TestGCFairness-2
    --- PASS: TestGCFairness-2 (1.04 seconds)
    === RUN TestPreemptSplitBig-2
    --- SKIP: TestPreemptSplitBig-2 (0.00 seconds)
        proc_test.go:299: skipping in -short mode
    === RUN TestSchedLocalQueue-2
    --- PASS: TestSchedLocalQueue-2 (0.00 seconds)
    === RUN TestSchedLocalQueueSteal-2
    --- PASS: TestSchedLocalQueueSteal-2 (0.00 seconds)
    === RUN TestRuntimeGogoBytes-2
    --- PASS: TestRuntimeGogoBytes-2 (0.27 seconds)
    === RUN TestStopCPUProfilingWithProfilerOff-2
    --- PASS: TestStopCPUProfilingWithProfilerOff-2 (0.00 seconds)
    === RUN TestFloat64-2
    --- PASS: TestFloat64-2 (0.12 seconds)
    === RUN TestStackSplit-2
    --- PASS: TestStackSplit-2 (0.02 seconds)
    === RUN TestStackMem-2
    --- PASS: TestStackMem-2 (0.00 seconds)
    === RUN TestCaller-2
    --- PASS: TestCaller-2 (0.01 seconds)
    === RUN TestSideEffectOrder-4
    --- PASS: TestSideEffectOrder-4 (0.00 seconds)
    === RUN TestAppendOverlap-4
    --- PASS: TestAppendOverlap-4 (0.00 seconds)
    === RUN TestChan-4
    --- PASS: TestChan-4 (0.78 seconds)
    === RUN TestSelfSelect-4
    --- PASS: TestSelfSelect-4 (0.01 seconds)
    === RUN TestSelectStress-4
    --- PASS: TestSelectStress-4 (0.59 seconds)
    === RUN TestChanSendInterface-4
    --- PASS: TestChanSendInterface-4 (0.00 seconds)
    === RUN TestPseudoRandomSend-4
    --- PASS: TestPseudoRandomSend-4 (0.00 seconds)
    === RUN TestMultiConsumer-4
    --- PASS: TestMultiConsumer-4 (0.28 seconds)
    === RUN TestCrashHandler-4
    --- PASS: TestCrashHandler-4 (0.54 seconds)
    === RUN TestSimpleDeadlock-4
    --- PASS: TestSimpleDeadlock-4 (0.23 seconds)
    === RUN TestInitDeadlock-4
    --- PASS: TestInitDeadlock-4 (0.23 seconds)
    === RUN TestLockedDeadlock-4
    --- PASS: TestLockedDeadlock-4 (0.22 seconds)
    === RUN TestLockedDeadlock2-4
    panic: test timed out after 1m0s
    
    goroutine 161404 [running]:
    runtime.panic(0x5f21c0, 0xc2080000c0)
        /home/aram/go/src/pkg/runtime/panic.c:250 +0xb4
    testing.func·007()
        /home/aram/go/src/pkg/testing/testing.go:604 +0x10a
    created by time.goFunc
        /home/aram/go/src/pkg/time/sleep.go:123 +0x47
    
    goroutine 16 [chan receive]:
    testing.RunTests(0x6e27c0, 0x971f00, 0x51, 0x51, 0x1)
        /home/aram/go/src/pkg/testing/testing.go:480 +0x9a8
    testing.Main(0x6e27c0, 0x971f00, 0x51, 0x51, 0x974320, ...)
        /home/aram/go/src/pkg/testing/testing.go:411 +0x8c
    main.main()
        /tmp/go-build049321118/runtime/_test/_testmain.go:537 +0x9c
    
    goroutine 422 [finalizer wait]:
    runtime.park(0x41caa0, 0x975368, 0x971d9d)
        /home/aram/go/src/pkg/runtime/proc.c:1364 +0x66
    runtime.parkunlock(0x975368, 0x971d9d)
        /home/aram/go/src/pkg/runtime/proc.c:1380 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2494 +0x7a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1438
    
    goroutine 161417 [syscall]:
    syscall.wait4(0x3862, 0xc20804870c, 0x0, 0xc208b91b00, 0x4262d2, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:243 +0x51
    syscall.Wait4(0x3862, 0xc20804870c, 0x0, 0xc208b91b00, 0x0, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:275 +0x5c
    os.(*Process).wait(0xc208d409e0, 0x0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec_unix.go:22 +0x123
    os.(*Process).Wait(0xc208d409e0, 0x413f4a, 0xc207fef758, 0x4)
        /home/aram/go/src/pkg/os/doc.go:43 +0x27
    os/exec.(*Cmd).Wait(0xc208bef680, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:315 +0x225
    os/exec.(*Cmd).Run(0xc208bef680, 0xc208108a10, 0xfffffd7fffdfffa7)
        /home/aram/go/src/pkg/os/exec/exec.go:237 +0x54
    os/exec.(*Cmd).CombinedOutput(0xc208bef680, 0xc208bef680, 0xfffffd7ffe687e38, 0x2, 0x2, ...)
        /home/aram/go/src/pkg/os/exec/exec.go:359 +0x2e3
    runtime_test.executeTest(0xc208b91b90, 0x732bf0, 0x9c, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/runtime/crash_test.go:58 +0x76a
    runtime_test.testDeadlock(0xc208b91b90, 0x732bf0, 0x9c)
        /home/aram/go/src/pkg/runtime/crash_test.go:89 +0x58
    runtime_test.TestLockedDeadlock2(0xc208b91b90)
        /home/aram/go/src/pkg/runtime/crash_test.go:109 +0x3b
    testing.tRunner(0xc208b91b90, 0x972020)
        /home/aram/go/src/pkg/testing/testing.go:398 +0x8b
    created by testing.RunTests
        /home/aram/go/src/pkg/testing/testing.go:479 +0x978
    
    goroutine 161419 [syscall]:
    syscall.Sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x4, 0xc20808d600, 0x200, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54
    syscall.read(0x4, 0xc20808d600, 0x200, 0x200, 0x5f2541, ...)
        /home/aram/go/src/pkg/syscall/zsyscall_solaris_amd64.go:500 +0xc5
    syscall.Read(0x4, 0xc20808d600, 0x200, 0x200, 0x4183d5, ...)
        /home/aram/go/src/pkg/syscall/syscall_unix.go:135 +0x5c
    os.(*File).read(0xc2081f9dd8, 0xc20808d600, 0x200, 0x200, 0x5cac40, ...)
        /home/aram/go/src/pkg/os/file_unix.go:183 +0x62
    os.(*File).Read(0xc2081f9dd8, 0xc20808d600, 0x200, 0x200, 0xfffffd7fff163ae8, ...)
        /home/aram/go/src/pkg/os/file.go:95 +0x98
    bytes.(*Buffer).ReadFrom(0xc208108a10, 0xfffffd7fff163a98, 0xc2081f9dd8, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/bytes/buffer.go:169 +0x274
    io.Copy(0xfffffd7fff163a48, 0xc208108a10, 0xfffffd7fff163a98, 0xc2081f9dd8, 0x0, ...)
        /home/aram/go/src/pkg/io/io.go:348 +0x124
    os/exec.func·003(0x5cbba0, 0xc2081089a0)
        /home/aram/go/src/pkg/os/exec/exec.go:212 +0x76
    os/exec.func·004(0xc208d40780)
        /home/aram/go/src/pkg/os/exec/exec.go:281 +0x2c
    created by os/exec.(*Cmd).Start
        /home/aram/go/src/pkg/os/exec/exec.go:282 +0xa26
    exit status 2
    FAIL    runtime 60.108s
    : oos:src; 

Disabling the GC fixes the problem:

    : oos:src; GOGC=off GOMAXPROCS=2 go test -short -timeout=120s -cpu=1,2,4 runtime
    --- FAIL: TestFinalizerType (20.05 seconds)
        mfinal_test.go:62: finalizer for type func(*int) didn't run
        mfinal_test.go:62: finalizer for type func(runtime_test.Tintptr) didn't run
        mfinal_test.go:62: finalizer for type func(*int) didn't run
        mfinal_test.go:62: finalizer for type func(*runtime_test.Tint) didn't run
        mfinal_test.go:62: finalizer for type func(runtime_test.Tinter) didn't run
    --- FAIL: TestFinalizerInterfaceBig (4.01 seconds)
        mfinal_test.go:100: finalizer for type *bigValue didn't run
    --- FAIL: TestFinalizerType-2 (20.05 seconds)
        mfinal_test.go:62: finalizer for type func(*int) didn't run
        mfinal_test.go:62: finalizer for type func(runtime_test.Tintptr) didn't run
        mfinal_test.go:62: finalizer for type func(*int) didn't run
        mfinal_test.go:62: finalizer for type func(*runtime_test.Tint) didn't run
        mfinal_test.go:62: finalizer for type func(runtime_test.Tinter) didn't run
    --- FAIL: TestFinalizerInterfaceBig-2 (4.01 seconds)
        mfinal_test.go:100: finalizer for type *bigValue didn't run
    --- FAIL: TestFinalizerType-4 (20.05 seconds)
        mfinal_test.go:62: finalizer for type func(*int) didn't run
        mfinal_test.go:62: finalizer for type func(runtime_test.Tintptr) didn't run
        mfinal_test.go:62: finalizer for type func(*int) didn't run
        mfinal_test.go:62: finalizer for type func(*runtime_test.Tint) didn't run
        mfinal_test.go:62: finalizer for type func(runtime_test.Tinter) didn't run
    --- FAIL: TestFinalizerInterfaceBig-4 (4.01 seconds)
        mfinal_test.go:100: finalizer for type *bigValue didn't run
    FAIL
    FAIL    runtime 105.348s
    : oos:src; 

This problem appeared in this commit:
    e1d8f23 (runtime: concurrent GC sweep)
    https://golang.org/cl/46430043.
    
This commit made tests pass again:
    bb13b99 (runtime: temporary disable concurrent GC sweep)
    https://golang.org/cl/62360043

This commit broke them again:
    a8b97f2 (runtime: fix concurrent GC sweep)
    https://golang.org/cl/62990043

Broken tests leave deadlocked processes behind:

    : oos:src; ps ax | grep go
       280 ?        S  0:00 go run /tmp/go-build293965775/main.go
       283 ?        S  0:00 go run /tmp/go-build293965775/main.go
      4859 ?        S  0:00 go run /tmp/go-build693490909/main.go
      4861 ?        S  0:00 go run /tmp/go-build693490909/main.go
      8595 ?        S  0:00 go run /tmp/go-build108964010/main.go
      8598 ?        S  0:00 go run /tmp/go-build108964010/main.go
      9437 ?        S  0:00 go run /tmp/go-build683078853/main.go
      9440 ?        S  0:00 go run /tmp/go-build683078853/main.go
      9529 ?        S  0:00 go run /tmp/go-build438915788/main.go
      9532 ?        S  0:00 go run /tmp/go-build438915788/main.go
     10881 ?        S  0:00 go run /tmp/go-build761453762/main.go
     10883 ?        S  0:00 go run /tmp/go-build761453762/main.go
     14011 ?        S  0:00 go run /tmp/go-build419394699/main.go
     14014 ?        S  0:00 go run /tmp/go-build419394699/main.go
     14434 ?        S  0:00 go run /tmp/go-build455132132/main.go
     14436 ?        S  0:00 go run /tmp/go-build455132132/main.go
     20864 ?        S  0:00 go run /tmp/go-build014179166/main.go
     20867 ?        S  0:00 go run /tmp/go-build014179166/main.go
     24230 ?        S  0:00 go run /tmp/go-build345783399/main.go
     24232 ?        S  0:00 go run /tmp/go-build345783399/main.go
     25435 ?        S  0:00 go run /tmp/go-build616491765/main.go
     25438 ?        S  0:00 go run /tmp/go-build616491765/main.go
     19922 pts/4    S  0:00 go run /tmp/go-build597897994/main.go
     19925 pts/4    S  0:00 go run /tmp/go-build597897994/main.go
     21272 pts/4    S  0:00 grep go
    : oos:src; 

The files are:

    package main
    import (
        "runtime"
        "time"
    )
    func main() {
        go func() {
            runtime.LockOSThread()
            select {}
        }()
        time.Sleep(time.Millisecond)
        select {}
    }

It looks like there's a problem with the deadlock detector.
@dvyukov
Copy link
Member

dvyukov commented Mar 11, 2014

Comment 1:

Please collect crash report with GOTRACEBACK=2 from the program that hangs (on linux it
requires sending SIGABRT to the process). It can shed some light on the issue.

@4ad
Copy link
Member Author

4ad commented Mar 11, 2014

Comment 2:

This is one:
    === RUN TestCrashHandler-4
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2d37a7
    
    goroutine 0 [idle]:
    
    goroutine 16 [chan receive]:
    runtime.park(0x4159c0, 0xc2081aee90, 0x8510cd)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xc2081aee90, 0x8510cd)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    chanrecv(0x5d1360, 0xc2081aee40, 0xc20808de00, 0x43e201, 0x0)
        /home/aram/go/src/pkg/runtime/chan.goc:266 +0x4e8
    runtime.chanrecv1(0x5d1360, 0xc2081aee40, 0xc20808de00)
        /home/aram/go/src/pkg/runtime/chan.goc:348 +0x38
    testing.RunTests(0x755350, 0x8537e0, 0x53, 0x53, 0x83bd01)
        /home/aram/go/src/pkg/testing/testing.go:504 +0x906
    testing.Main(0x755350, 0x8537e0, 0x53, 0x53, 0x855cc0, ...)
        /home/aram/go/src/pkg/testing/testing.go:435 +0x9e
    main.main()
        /tmp/go-build133379301/runtime/_test/_testmain.go:551 +0x9c
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x4159c0, 0x856d88, 0x8534ac)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x856d88, 0x8534ac)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 24 [timer goroutine (idle)]:
    runtime.park(0x4159c0, 0x857be0, 0x84fa46)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x857be0, 0x84fa46)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    timerproc()
        /home/aram/go/src/pkg/runtime/time.goc:238 +0x75
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by addtimer
        /home/aram/go/src/pkg/runtime/time.goc:100
    
    goroutine 401 [finalizer wait]:
    runtime.park(0x4159c0, 0x856d88, 0x853695)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x856d88, 0x853695)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 161381 [syscall]:
    runtime.cgocall(0x42e910, 0xfffffd7ffee23c50)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x4, 0xc20925c200, 0x200, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54
    syscall.read(0x4, 0xc20925c200, 0x200, 0x200, 0x5f7e61, ...)
        /home/aram/go/src/pkg/syscall/zsyscall_solaris_amd64.go:500 +0xef
    syscall.Read(0x4, 0xc20925c200, 0x200, 0x200, 0x411214, ...)
        /home/aram/go/src/pkg/syscall/syscall_unix.go:135 +0x6e
    os.(*File).read(0xc208056320, 0xc20925c200, 0x200, 0x200, 0x5d0280, ...)
        /home/aram/go/src/pkg/os/file_unix.go:178 +0x74
    os.(*File).Read(0xc208056320, 0xc20925c200, 0x200, 0x200, 0xfffffd7ffee23f20, ...)
        /home/aram/go/src/pkg/os/file.go:95 +0xc2
    bytes.(*Buffer).ReadFrom(0xc208280930, 0xfffffd7fff163d18, 0xc208056320, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/bytes/buffer.go:169 +0x22a
    io.Copy(0xfffffd7fff163cc8, 0xc208280930, 0xfffffd7fff163d18, 0xc208056320, 0x0, ...)
        /home/aram/go/src/pkg/io/io.go:348 +0x153
    os/exec.func·003(0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:212 +0x86
    os/exec.func·004(0xc2081d44a0)
        /home/aram/go/src/pkg/os/exec/exec.go:284 +0x3e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/exec.(*Cmd).Start
        /home/aram/go/src/pkg/os/exec/exec.go:285 +0x8db
    
    goroutine 161379 [syscall]:
    runtime.cgocall(0x42e910, 0xc2081cda58)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
    syscall.wait4(0x5ddd, 0xc20803d5b8, 0x0, 0xc2092465a0, 0x427352, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:243 +0x51
    syscall.Wait4(0x5ddd, 0xc20803d5b8, 0x0, 0xc2092465a0, 0xc20909bcc0, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:275 +0x6e
    os.(*Process).wait(0xc2081d46c0, 0x0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec_unix.go:22 +0x130
    os.(*Process).Wait(0xc2081d46c0, 0xc208234ff0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/doc.go:45 +0x39
    os/exec.(*Cmd).Wait(0xc2080432c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:320 +0x1bd
    os/exec.(*Cmd).Run(0xc2080432c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:237 +0x78
    os/exec.(*Cmd).CombinedOutput(0xc2080432c0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/os/exec/exec.go:364 +0x269
    runtime_test.executeTest(0xc209246480, 0x75c710, 0x23c, 0x5cb060, 0xc20803d1b8, ...)
        /home/aram/go/src/pkg/runtime/crash_test.go:58 +0x710
    runtime_test.testCrashHandler(0xc209246480, 0x0)
        /home/aram/go/src/pkg/runtime/crash_test.go:77 +0x88
    runtime_test.TestCrashHandler(0xc209246480)
        /home/aram/go/src/pkg/runtime/crash_test.go:85 +0x2c
    testing.tRunner(0xc209246480, 0x8538a0)
        /home/aram/go/src/pkg/testing/testing.go:422 +0x9d
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by testing.RunTests
        /home/aram/go/src/pkg/testing/testing.go:503 +0x8d6
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0xfffffd7ffefa1000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7fffdfefd0
    rsp     0xfffffd7fffdfef68
    r8      0xfffffd7ffef94e40
    r9      0x6e
    r10     0xfffffd7ffefa1000
    r11     0x5
    r12     0x878720
    r13     0xfffffd7fff34ca00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2d37a7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
    exit status 2
    FAIL    runtime 70.596s
    : oos:runtime; 
This is another:
    === RUN TestCrashHandler-2
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2d37a7
    
    goroutine 0 [idle]:
    
    goroutine 16 [chan receive]:
    runtime.park(0x4159c0, 0xc2081a2b30, 0x8510cd)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xc2081a2b30, 0x8510cd)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    chanrecv(0x5d1360, 0xc2081a2ae0, 0xc2081dde00, 0x43e201, 0x0)
        /home/aram/go/src/pkg/runtime/chan.goc:266 +0x4e8
    runtime.chanrecv1(0x5d1360, 0xc2081a2ae0, 0xc2081dde00)
        /home/aram/go/src/pkg/runtime/chan.goc:348 +0x38
    testing.RunTests(0x755350, 0x8537e0, 0x53, 0x53, 0x83bd01)
        /home/aram/go/src/pkg/testing/testing.go:504 +0x906
    testing.Main(0x755350, 0x8537e0, 0x53, 0x53, 0x855cc0, ...)
        /home/aram/go/src/pkg/testing/testing.go:435 +0x9e
    main.main()
        /tmp/go-build453067945/runtime/_test/_testmain.go:551 +0x9c
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x4159c0, 0x856d88, 0x8534ac)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x856d88, 0x8534ac)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 24 [timer goroutine (idle)]:
    runtime.park(0x4159c0, 0x857be0, 0x84fa46)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x857be0, 0x84fa46)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    timerproc()
        /home/aram/go/src/pkg/runtime/time.goc:238 +0x75
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by addtimer
        /home/aram/go/src/pkg/runtime/time.goc:100
    
    goroutine 379 [finalizer wait]:
    runtime.park(0x4159c0, 0x856d88, 0x853695)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x856d88, 0x853695)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 80894 [syscall]:
    runtime.cgocall(0x42e910, 0xfffffd7ffe6e3c50)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x4, 0xc208eb2400, 0x200, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54
    syscall.read(0x4, 0xc208eb2400, 0x200, 0x200, 0x5f7e61, ...)
        /home/aram/go/src/pkg/syscall/zsyscall_solaris_amd64.go:500 +0xef
    syscall.Read(0x4, 0xc208eb2400, 0x200, 0x200, 0x411214, ...)
        /home/aram/go/src/pkg/syscall/syscall_unix.go:135 +0x6e
    os.(*File).read(0xc208086370, 0xc208eb2400, 0x200, 0x200, 0x5d0280, ...)
        /home/aram/go/src/pkg/os/file_unix.go:178 +0x74
    os.(*File).Read(0xc208086370, 0xc208eb2400, 0x200, 0x200, 0x410cc8, ...)
        /home/aram/go/src/pkg/os/file.go:95 +0xc2
    bytes.(*Buffer).ReadFrom(0xc2080d4d20, 0xfffffd7fff163ee8, 0xc208086370, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/bytes/buffer.go:169 +0x22a
    io.Copy(0xfffffd7fff163e98, 0xc2080d4d20, 0xfffffd7fff163ee8, 0xc208086370, 0x0, ...)
        /home/aram/go/src/pkg/io/io.go:348 +0x153
    os/exec.func·003(0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:212 +0x86
    os/exec.func·004(0xc20829a420)
        /home/aram/go/src/pkg/os/exec/exec.go:284 +0x3e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/exec.(*Cmd).Start
        /home/aram/go/src/pkg/os/exec/exec.go:285 +0x8db
    
    goroutine 80919 [syscall]:
    runtime.cgocall(0x42e910, 0xc208ea9a58)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
    syscall.wait4(0x5e71, 0xc20803d8a8, 0x0, 0xc208e567e0, 0x427352, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:243 +0x51
    syscall.Wait4(0x5e71, 0xc20803d8a8, 0x0, 0xc208e567e0, 0xc20802f770, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:275 +0x6e
    os.(*Process).wait(0xc20829a640, 0x0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec_unix.go:22 +0x130
    os.(*Process).Wait(0xc20829a640, 0xc2081f4fc0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/doc.go:45 +0x39
    os/exec.(*Cmd).Wait(0xc208042c80, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:320 +0x1bd
    os/exec.(*Cmd).Run(0xc208042c80, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:237 +0x78
    os/exec.(*Cmd).CombinedOutput(0xc208042c80, 0x0, 0x0, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/os/exec/exec.go:364 +0x269
    runtime_test.executeTest(0xc208da9d40, 0x75c710, 0x23c, 0x5cb060, 0xc20803d498, ...)
        /home/aram/go/src/pkg/runtime/crash_test.go:58 +0x710
    runtime_test.testCrashHandler(0xc208da9d40, 0x0)
        /home/aram/go/src/pkg/runtime/crash_test.go:77 +0x88
    runtime_test.TestCrashHandler(0xc208da9d40)
        /home/aram/go/src/pkg/runtime/crash_test.go:85 +0x2c
    testing.tRunner(0xc208da9d40, 0x8538a0)
        /home/aram/go/src/pkg/testing/testing.go:422 +0x9d
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by testing.RunTests
        /home/aram/go/src/pkg/testing/testing.go:503 +0x8d6
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0xfffffd7ffefa1000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7fffdfefd0
    rsp     0xfffffd7fffdfef68
    r8      0xfffffd7ffef94e40
    r9      0x4e
    r10     0xfffffd7ffefa1000
    r11     0x858f10
    r12     0x878720
    r13     0xfffffd7fff34ca00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2d37a7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
    exit status 2
    FAIL    runtime 51.119s
    : oos:runtime; 
And another one:
    === RUN TestRecursivePanic
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2da63a
    signal arrived during cgo execution
    
    goroutine 410 [syscall]:
    runtime.cgocall(0x42e910, 0xfffffd7ffebaac50)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xfffffd7ffebaac40
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x4, 0xc208088e00, 0x200, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xfffffd7ffebaac88
    syscall.read(0x4, 0xc208088e00, 0x200, 0x200, 0x5f7e61, ...)
        /home/aram/go/src/pkg/syscall/zsyscall_solaris_amd64.go:500 +0xef fp=0xfffffd7ffebaacf8
    syscall.Read(0x4, 0xc208088e00, 0x200, 0x200, 0x411214, ...)
        /home/aram/go/src/pkg/syscall/syscall_unix.go:135 +0x6e fp=0xfffffd7ffebaad38
    os.(*File).read(0xc208054408, 0xc208088e00, 0x200, 0x200, 0x5d0280, ...)
        /home/aram/go/src/pkg/os/file_unix.go:178 +0x74 fp=0xfffffd7ffebaad78
    os.(*File).Read(0xc208054408, 0xc208088e00, 0x200, 0x200, 0xfffffd7ffebaaf40, ...)
        /home/aram/go/src/pkg/os/file.go:95 +0xc2 fp=0xfffffd7ffebaadd0
    bytes.(*Buffer).ReadFrom(0xc2081b6bd0, 0xfffffd7fff163e08, 0xc208054408, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/bytes/buffer.go:169 +0x22a fp=0xfffffd7ffebaae78
    io.Copy(0xfffffd7fff163db8, 0xc2081b6bd0, 0xfffffd7fff163e08, 0xc208054408, 0x0, ...)
        /home/aram/go/src/pkg/io/io.go:348 +0x153 fp=0xfffffd7ffebaaf18
    os/exec.func·003(0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:212 +0x86 fp=0xfffffd7ffebaaf68
    os/exec.func·004(0xc20811dae0)
        /home/aram/go/src/pkg/os/exec/exec.go:284 +0x3e fp=0xfffffd7ffebaafa0
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xfffffd7ffebaafa8
    created by os/exec.(*Cmd).Start
        /home/aram/go/src/pkg/os/exec/exec.go:285 +0x8db
    
    goroutine 16 [chan receive]:
    runtime.park(0x4159c0, 0xc20804c770, 0x8510cd)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xc20804c770, 0x8510cd)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    chanrecv(0x5d1360, 0xc20804c720, 0xc208109e00, 0x43e201, 0x0)
        /home/aram/go/src/pkg/runtime/chan.goc:266 +0x4e8
    runtime.chanrecv1(0x5d1360, 0xc20804c720, 0xc208109e00)
        /home/aram/go/src/pkg/runtime/chan.goc:348 +0x38
    testing.RunTests(0x755350, 0x8537e0, 0x53, 0x53, 0x83bd01)
        /home/aram/go/src/pkg/testing/testing.go:504 +0x906
    testing.Main(0x755350, 0x8537e0, 0x53, 0x53, 0x855cc0, ...)
        /home/aram/go/src/pkg/testing/testing.go:435 +0x9e
    main.main()
        /tmp/go-build464157307/runtime/_test/_testmain.go:551 +0x9c
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x4159c0, 0x856d88, 0x8534ac)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x856d88, 0x8534ac)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 407 [syscall]:
    runtime.cgocall(0x42e910, 0xfffffd7ffefb0a58)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
    syscall.wait4(0x5ff8, 0xc208001ee8, 0x0, 0xc20806a990, 0x427352, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:243 +0x51
    syscall.Wait4(0x5ff8, 0xc208001ee8, 0x0, 0xc20806a990, 0xc20817ae10, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:275 +0x6e
    os.(*Process).wait(0xc20811dd00, 0x0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec_unix.go:22 +0x130
    os.(*Process).Wait(0xc20811dd00, 0xc208043b60, 0x0, 0x0)
        /home/aram/go/src/pkg/os/doc.go:45 +0x39
    os/exec.(*Cmd).Wait(0xc2080412c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:320 +0x1bd
    os/exec.(*Cmd).Run(0xc2080412c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:237 +0x78
    os/exec.(*Cmd).CombinedOutput(0xc2080412c0, 0x0, 0x0, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/os/exec/exec.go:364 +0x269
    runtime_test.executeTest(0xc20806a870, 0x75c250, 0x12c, 0x0, 0x0, ...)
        /home/aram/go/src/pkg/runtime/crash_test.go:58 +0x710
    runtime_test.TestRecursivePanic(0xc20806a870)
        /home/aram/go/src/pkg/runtime/crash_test.go:136 +0x63
    testing.tRunner(0xc20806a870, 0x853960)
        /home/aram/go/src/pkg/testing/testing.go:422 +0x9d
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by testing.RunTests
        /home/aram/go/src/pkg/testing/testing.go:503 +0x8d6
    
    goroutine 24 [timer goroutine (idle)]:
    runtime.park(0x4159c0, 0x857be0, 0x84fa46)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x857be0, 0x84fa46)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    timerproc()
        /home/aram/go/src/pkg/runtime/time.goc:238 +0x75
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by addtimer
        /home/aram/go/src/pkg/runtime/time.goc:100
    
    goroutine 386 [finalizer wait]:
    runtime.park(0x4159c0, 0x856d88, 0x853695)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0x856d88, 0x853695)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0x0
    rdx     0x200
    rdi     0x4
    rsi     0xc208088e00
    rbp     0xfffffd7fffdff100
    rsp     0xfffffd7fffdff0c8
    r8      0x0
    r9      0x0
    r10     0x0
    r11     0xfffffd7ffebaac98
    r12     0x666740
    r13     0xc20806e080
    r14     0x2
    r15     0xc208043300
    rip     0xfffffd7fff2da63a
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
    exit status 2
    FAIL    runtime 30.779s
    : oos:runtime;

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 3:

I meant crash dump of this program:
    package main
    import (
        "runtime"
        "time"
    )
    func main() {
        go func() {
            runtime.LockOSThread()
            select {}
        }()
        time.Sleep(time.Millisecond)
        select {}
    }
The problem is with it, right?

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 4:

This program:
    
    package main
    
    import (
        "fmt"
        "runtime"
    )
    
    func main() {
        runtime.GOMAXPROCS(1)
        memstats := new(runtime.MemStats)
        runtime.GC()
        runtime.ReadMemStats(memstats)
        sys := memstats.Sys
    
        runtime.MemProfileRate = 0 // disable profiler
    
        itercount := 1000000
    
        itercount = 100000
    
        for i := 0; i < itercount; i++ {
            workthegc()
        }
    
        // Should only be using a few MB.
        // We allocated 100 MB or (if not short) 1 GB.
        runtime.ReadMemStats(memstats)
        if sys > memstats.Sys {
            sys = 0
        } else {
            sys = memstats.Sys - sys
        }
        if sys > 16<<20 {
            fmt.Printf("using too much memory: %d bytes\n", sys)
            return
        }
        fmt.Printf("OK\n")
    }
    
    func workthegc() []byte {
        return make([]byte, 1029)
    }
Has this crashdump:
    --- FAIL: TestGcSys-2 (257.96 seconds)
        gc_test.go:22: expected "OK\n", but got "SIGABRT: used by abort, replace SIGIOT in the future\nPC=0xfffffd7fff2d37a7\nsignal arrived during cgo execution\n\ngoroutine 22 [runnable]:\ncreated by main.(*builder).do\n\t/home/aram/go/src/cmd/go/build.go:745 +0x416\n\ngoroutine 16 [semacquire, 4 minutes]:\nsync.runtime_Semacquire(0xc2080fdcd0)\n\t/home/aram/go/src/pkg/runtime/sema.goc:199 +0x30\nsync.(*WaitGroup).Wait(0xc2080f4e20)\n\t/home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d\nmain.(*builder).do(0xc208102000, 0xc208001ba0)\n\t/home/aram/go/src/cmd/go/build.go:748 +0x440\nmain.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)\n\t/home/aram/go/src/cmd/go/run.go:115 +0x84f\nmain.main()\n\t/home/aram/go/src/cmd/go/main.go:161 +0x4fa\n\ngoroutine 19 [syscall, 4 minutes]:\nos/signal.loop()\n\t/home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e\ncreated by os/signal.init·1\n\t/home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32\n\ngoroutine 21 [select, 4 minutes]:\nmain.func·006()\n\t/home/aram/go/src/cmd/go/build.go:729 +0x1a7\ncreated by main.(*builder).do\n\t/home/aram/go/src/cmd/go/build.go:745 +0x416\n\ngoroutine 32 [running]:\n\tgoroutine running on other thread; stack unavailable\n\nrax     0x5b\nrbx     0xfffffd7fff192a40\nrcx     0xfffffd7ffee0d000\nrdx     0x0\nrdi     0x0\nrsi     0x0\nrbp     0xfffffd7fffdfef50\nrsp     0xfffffd7fffdfeee8\nr8      0xfffffd7ffef9c140\nr9      0x2e\nr10     0xfffffd7ffee0d000\nr11     0x286\nr12     0xb32280\nr13     0xfffffd7fff34ca00\nr14     0x0\nr15     0x0\nrip     0xfffffd7fff2d37a7\nrflags  0x247\ncs      0x53\nfs      0x0\ngs      0x0\ngo build command-line-arguments: exit status 2\n"
Sorry for the mangling, I guess I can use DTrace to extract it directly
from the write to the fd.
This other program:
    
    package main
    
    import (
        "runtime"
        "runtime/debug"
    )
    
    func main() {
        debug.SetMaxThreads(10)
        c := make(chan int)
        for i := 0; i < 100; i++ {
            go func() {
                runtime.LockOSThread()
                c <- 0
                select{}
            }()
            <-c
        }
    }
has this crashdump:
    --- FAIL: TestThreadExhaustion-4 (74.58 seconds)
        crash_test.go:131: output does not start with "runtime: program exceeds 10-thread limit\nfatal error: thread exhaustion":
            SIGABRT: used by abort, replace SIGIOT in the future
            PC=0xfffffd7fff2d37a7
            signal arrived during cgo execution
            
            goroutine 22 [runnable]:
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 16 [semacquire, 1 minutes]:
            sync.runtime_Semacquire(0xc20804fbc8)
                /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
            sync.(*WaitGroup).Wait(0xc208170a20)
                /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
            main.(*builder).do(0xc208110d20, 0xc2080e9c70)
                /home/aram/go/src/cmd/go/build.go:748 +0x440
            main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
                /home/aram/go/src/cmd/go/run.go:115 +0x84f
            main.main()
                /home/aram/go/src/cmd/go/main.go:161 +0x4fa
            
            goroutine 19 [syscall, 1 minutes]:
            os/signal.loop()
                /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
            created by os/signal.init·1
                /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
            
            goroutine 21 [select, 1 minutes]:
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:729 +0x1a7
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 32 [chan receive, 1 minutes]:
            main.func·028()
                /home/aram/go/src/cmd/go/signal.go:21 +0x3b
            created by main.processSignals
                /home/aram/go/src/cmd/go/signal.go:23 +0xc3
            
            goroutine 33 [running]:
                goroutine running on other thread; stack unavailable
            
            rax     0x5b
            rbx     0xfffffd7ffef52240
            rcx     0xfffffd7ffee02000
            rdx     0x0
            rdi     0x0
            rsi     0x0
            rbp     0xfffffd7ffddffe70
            rsp     0xfffffd7ffddffe08
            r8      0xfffffd7ffefa6140
            r9      0x68
            r10     0xfffffd7ffee02000
            r11     0x286
            r12     0xb32380
            r13     0xfffffd7fff34ca00
            r14     0x0
            r15     0x0
            rip     0xfffffd7fff2d37a7
            rflags  0x247
            cs      0x53
            fs      0x0
            gs      0x0
            exit status 2

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 5:

This is go test crashdump, I'm including it because now go test itself
deadlocked before starting any test. This is one of the deadlocked go
test processes:
    : oos:go; GOMAXPROCS=2 go test -v -short -cpu=1,2,4 runtime
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2da63a
    signal arrived during cgo execution
    
    goroutine 22 [syscall]:
    runtime.cgocall(0x4849f0, 0xc20847ec58)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xc20847ec48
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc20847ed70, 0x8, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xc20847ec90
    syscall.readlen(0x6, 0xc20847ed70, 0x8, 0x10, 0x0, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa fp=0xc20847ecf8
    syscall.forkExec(0xc2080317a0, 0x27, 0xc2084240f0, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8 fp=0xc20847ee28
    syscall.StartProcess(0xc2080317a0, 0x27, 0xc2084240f0, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc20847ee78
    os.startProcess(0xc2080317a0, 0x27, 0xc2084240f0, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc20847efa0
    os.StartProcess(0xc2080317a0, 0x27, 0xc2084240f0, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc20847eff0
    os/exec.(*Cmd).Start(0xc20847a140, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc20847f190
    os/exec.(*Cmd).Run(0xc20847a140, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc20847f1c0
    main.(*builder).runOut(0xc208102070, 0xc208054980, 0x1d, 0xfffffd7fffdff365, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc20847f2d8
    main.(*builder).run(0xc208102070, 0xc208054980, 0x1d, 0xfffffd7fffdff365, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1325 +0xe6 fp=0xc20847f3d0
    main.gcToolchain.cc(0xc208102070, 0xc20809a800, 0xc20846c600, 0x2f, 0xc20847c100, ...)
        /home/aram/go/src/cmd/go/build.go:1782 +0x949 fp=0xc20847f6d0
    main.gcToolchain.cc·i(0x0, 0xc208102070, 0xc20809a800, 0xc20846c600, 0x2f, ...)
        /home/aram/go/src/cmd/go/build.go:1 +0xa3 fp=0xc20847f728
    main.(*builder).build(0xc208102070, 0xc208470000, 0x0, 0x0)
        /home/aram/go/src/cmd/go/build.go:956 +0x2ce8 fp=0xc20847fea8
    main.func·005(0xc208470000)
        /home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc20847ff50
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc20847ffa8
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc20847ffb0
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire, 1 minutes]:
    sync.runtime_Semacquire(0xc208449158)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208461220)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc208102070, 0xc208472270)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x4, 0x4)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    
    goroutine 19 [syscall, 1 minutes]:
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 32 [finalizer wait, 1 minutes]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e6b5)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    
    goroutine 21 [select, 1 minutes]:
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0x0
    rdx     0x8
    rdi     0x6
    rsi     0xc20847ed70
    rbp     0xfffffd7fffdff020
    rsp     0xfffffd7fffdfefe8
    r8      0x0
    r9      0x0
    r10     0x0
    r11     0xb14cf0
    r12     0x811a40
    r13     0x0
    r14     0xc208438fc0
    r15     0x10
    rip     0xfffffd7fff2da63a
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
    : oos:go; 
And this is the other deadlocked go test process:
    
    : oos:go; SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2d37a7
    signal arrived during cgo execution
    
    goroutine 22 [runnable]:
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire, 2 minutes]:
    sync.runtime_Semacquire(0xc208449158)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208461220)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc208102070, 0xc208472270)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x4, 0x4)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    
    goroutine 19 [syscall, 2 minutes]:
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 32 [running]:
        goroutine running on other thread; stack unavailable
    
    goroutine 21 [select, 2 minutes]:
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0xfffffd7ffee05000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7fffdfef50
    rsp     0xfffffd7fffdfeee8
    r8      0xfffffd7ffefa4140
    r9      0x3a
    r10     0xfffffd7ffee05000
    r11     0x286
    r12     0xb32280
    r13     0xfffffd7fff34ca00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2d37a7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 6:

This is TestGcSys with a different crash dump:
    --- FAIL: TestGcSys (65.91 seconds)
        gc_test.go:22: expected "OK\n", but got "SIGABRT: used by abort, replace SIGIOT in the future\nPC=0xfffffd7fff2da63a\nsignal arrived during cgo execution\n\ngoroutine 21 [syscall]:\nruntime.cgocall(0x4849f0, 0xc2081aec98)\n\t/home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xc2081aec88\nsyscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc2081aedb0, 0x8, ...)\n\t/home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xc2081aecd0\nsyscall.readlen(0x6, 0xc2081aedb0, 0x8, 0x9, 0x0, ...)\n\t/home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa fp=0xc2081aed38\nsyscall.forkExec(0xc20818bf50, 0x27, 0xc2081ac480, 0x8, 0x8, ...)\n\t/home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8 fp=0xc2081aee68\nsyscall.StartProcess(0xc20818bf50, 0x27, 0xc2081ac480, 0x8, 0x8, ...)\n\t/home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc2081aeeb8\nos.startProcess(0xc20818bf50, 0x27, 0xc2081ac480, 0x8, 0x8, ...)\n\t/home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc2081aefe0\nos.StartProcess(0xc20818bf50, 0x27, 0xc2081ac480, 0x8, 0x8, ...)\n\t/home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc2081af030\nos/exec.(*Cmd).Start(0xc2081b0000, 0x0, 0x0)\n\t/home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc2081af1d0\nos/exec.(*Cmd).Run(0xc2081b0000, 0x0, 0x0)\n\t/home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc2081af200\nmain.(*builder).runOut(0xc20810ed20, 0x825df0, 0x1, 0x865b50, 0x16, ...)\n\t/home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc2081af318\nmain.(*builder).run(0xc20810ed20, 0x825df0, 0x1, 0x865b50, 0x16, ...)\n\t/home/aram/go/src/cmd/go/build.go:1325 +0xe6 fp=0xc2081af410\nmain.gcToolchain.ld(0xc20810ed20, 0xc20806e000, 0xc2081639c0, 0x3b, 0xc2081ac300, ...)\n\t/home/aram/go/src/cmd/go/build.go:1775 +0x1091 fp=0xc2081af6b0\nmain.gcToolchain.ld·i(0x0, 0xc20810ed20, 0xc20806e000, 0xc2081639c0, 0x3b, ...)\n\t/home/aram/go/src/cmd/go/build.go:1 +0xe3 fp=0xc2081af728\nmain.(*builder).build(0xc20810ed20, 0xc208000270, 0x0, 0x0)\n\t/home/aram/go/src/cmd/go/build.go:999 +0x3825 fp=0xc2081afea8\nmain.func·005(0xc208000270)\n\t/home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc2081aff50\nmain.func·006()\n\t/home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc2081affa8\nruntime.goexit()\n\t/home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc2081affb0\ncreated by main.(*builder).do\n\t/home/aram/go/src/cmd/go/build.go:745 +0x416\n\ngoroutine 16 [semacquire]:\nsync.runtime_Semacquire(0xc2080ca960)\n\t/home/aram/go/src/pkg/runtime/sema.goc:199 +0x30\nsync.(*WaitGroup).Wait(0xc20819ce20)\n\t/home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d\nmain.(*builder).do(0xc20810ed20, 0xc2080016c0)\n\t/home/aram/go/src/cmd/go/build.go:748 +0x440\nmain.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)\n\t/home/aram/go/src/cmd/go/run.go:115 +0x84f\nmain.main()\n\t/home/aram/go/src/cmd/go/main.go:161 +0x4fa\n\ngoroutine 19 [syscall]:\nos/signal.loop()\n\t/home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e\ncreated by os/signal.init·1\n\t/home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32\n\ngoroutine 20 [select]:\nmain.func·006()\n\t/home/aram/go/src/cmd/go/build.go:729 +0x1a7\ncreated by main.(*builder).do\n\t/home/aram/go/src/cmd/go/build.go:745 +0x416\n\ngoroutine 33 [finalizer wait]:\nruntime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)\n\t/home/aram/go/src/pkg/runtime/proc.c:1372 +0x89\nruntime.parkunlock(0xb10ec0, 0xb0e6b5)\n\t/home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b\nrunfinq()\n\t/home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2\nruntime.goexit()\n\t/home/aram/go/src/pkg/runtime/proc.c:1448\n\nrax     0x5b\nrbx     0xfffffd7fff192a40\nrcx     0x0\nrdx     0x8\nrdi     0x6\nrsi     0xc2081aedb0\nrbp     0xfffffd7fffdff020\nrsp     0xfffffd7fffdfefe8\nr8      0x0\nr9      0x0\nr10     0x0\nr11     0xb14cf0\nr12     0x811a40\nr13     0x717020\nr14     0x0\nr15     0x10\nrip     0xfffffd7fff2da63a\nrflags  0x247\ncs      0x53\nfs      0x0\ngs      0x0\nSIGABRT: used by abort, replace SIGIOT in the future\nPC=0xfffffd7fff2d37a7\nsignal arrived during cgo execution\n\ngoroutine 21 [runnable]:\ncreated by main.(*builder).do\n\t/home/aram/go/src/cmd/go/build.go:745 +0x416\n\ngoroutine 16 [semacquire, 1 minutes]:\nsync.runtime_Semacquire(0xc2080ca960)\n\t/home/aram/go/src/pkg/runtime/sema.goc:199 +0x30\nsync.(*WaitGroup).Wait(0xc20819ce20)\n\t/home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d\nmain.(*builder).do(0xc20810ed20, 0xc2080016c0)\n\t/home/aram/go/src/cmd/go/build.go:748 +0x440\nmain.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)\n\t/home/aram/go/src/cmd/go/run.go:115 +0x84f\nmain.main()\n\t/home/aram/go/src/cmd/go/main.go:161 +0x4fa\n\ngoroutine 19 [syscall, 1 minutes]:\nos/signal.loop()\n\t/home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e\ncreated by os/signal.init·1\n\t/home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32\n\ngoroutine 20 [select, 1 minutes]:\nmain.func·006()\n\t/home/aram/go/src/cmd/go/build.go:729 +0x1a7\ncreated by main.(*builder).do\n\t/home/aram/go/src/cmd/go/build.go:745 +0x416\n\ngoroutine 33 [running]:\n\tgoroutine running on other thread; stack unavailable\n\nrax     0x5b\nrbx     0xfffffd7fff192a40\nrcx     0xfffffd7ffee0c000\nrdx     0x0\nrdi     0x0\nrsi     0x0\nrbp     0xfffffd7fffdfef50\nrsp     0xfffffd7fffdfeee8\nr8      0xfffffd7ffef99140\nr9      0x16\nr10     0xfffffd7ffee0c000\nr11     0x286\nr12     0xb32280\nr13     0xfffffd7fff34ca00\nr14     0x0\nr15     0x0\nrip     0xfffffd7fff2d37a7\nrflags  0x247\ncs      0x53\nfs      0x0\ngs      0x0\n"

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 7:

This program also deadlocks:
    package main
    
    import (
        "fmt"
        "runtime"
    )
    
    
    
    func test(name string) {
        defer func() {
            if x := recover(); x != nil {
                fmt.Printf(" recovered")
            }
            fmt.Printf(" done\n")
        }()
        fmt.Printf("%s:", name)
        var s *string
        _ = *s
        fmt.Print("SHOULD NOT BE HERE")
    }
    
    func testInNewThread(name string) {
        c := make(chan bool)
        go func() {
            runtime.LockOSThread()
            test(name)
            c <- true
        }()
        <-c
    }
    
    func main() {
        runtime.LockOSThread()
        test("main")
        testInNewThread("new-thread")
        testInNewThread("second-new-thread")
        test("main-again")
    }
This is the crashdump (actually two):
    === RUN TestCrashHandler-2
    --- FAIL: TestCrashHandler-2 (44.57 seconds)
        crash_test.go:80: output:
            SIGABRT: used by abort, replace SIGIOT in the future
            PC=0xfffffd7fff2da63a
            signal arrived during cgo execution
            
            goroutine 22 [syscall]:
            runtime.cgocall(0x4849f0, 0xc2081a8c98)
                /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xc2081a8c88
            syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc2081a8db0, 0x8, ...)
                /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xc2081a8cd0
            syscall.readlen(0x6, 0xc2081a8db0, 0x8, 0x9, 0x0, ...)
                /home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa fp=0xc2081a8d38
            syscall.forkExec(0xc208111f50, 0x27, 0xc2081a6480, 0x8, 0x8, ...)
                /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8 fp=0xc2081a8e68
            syscall.StartProcess(0xc208111f50, 0x27, 0xc2081a6480, 0x8, 0x8, ...)
                /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc2081a8eb8
            os.startProcess(0xc208111f50, 0x27, 0xc2081a6480, 0x8, 0x8, ...)
                /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc2081a8fe0
            os.StartProcess(0xc208111f50, 0x27, 0xc2081a6480, 0x8, 0x8, ...)
                /home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc2081a9030
            os/exec.(*Cmd).Start(0xc2080d9cc0, 0x0, 0x0)
                /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc2081a91d0
            os/exec.(*Cmd).Run(0xc2080d9cc0, 0x0, 0x0)
                /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc2081a9200
            main.(*builder).runOut(0xc208100000, 0x825df0, 0x1, 0x865b50, 0x16, ...)
                /home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc2081a9318
            main.(*builder).run(0xc208100000, 0x825df0, 0x1, 0x865b50, 0x16, ...)
                /home/aram/go/src/cmd/go/build.go:1325 +0xe6 fp=0xc2081a9410
            main.gcToolchain.ld(0xc208100000, 0xc20806e000, 0xc2080999c0, 0x3b, 0xc2081a6300, ...)
                /home/aram/go/src/cmd/go/build.go:1775 +0x1091 fp=0xc2081a96b0
            main.gcToolchain.ld·i(0x0, 0xc208100000, 0xc20806e000, 0xc2080999c0, 0x3b, ...)
                /home/aram/go/src/cmd/go/build.go:1 +0xe3 fp=0xc2081a9728
            main.(*builder).build(0xc208100000, 0xc2080001a0, 0x0, 0x0)
                /home/aram/go/src/cmd/go/build.go:999 +0x3825 fp=0xc2081a9ea8
            main.func·005(0xc2080001a0)
                /home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc2081a9f50
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc2081a9fa8
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc2081a9fb0
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 16 [semacquire]:
            sync.runtime_Semacquire(0xc2080fdf00)
                /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
            sync.(*WaitGroup).Wait(0xc20811ae20)
                /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
            main.(*builder).do(0xc208100000, 0xc208001ee0)
                /home/aram/go/src/cmd/go/build.go:748 +0x440
            main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
                /home/aram/go/src/cmd/go/run.go:115 +0x84f
            main.main()
                /home/aram/go/src/cmd/go/main.go:161 +0x4fa
            
            goroutine 19 [syscall]:
            os/signal.loop()
                /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
            created by os/signal.init·1
                /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
            
            goroutine 21 [select]:
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:729 +0x1a7
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 32 [finalizer wait]:
            runtime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xb10ec0, 0xb0e6b5)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            runfinq()
                /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            
            rax     0x5b
            rbx     0xfffffd7fff192a40
            rcx     0x0
            rdx     0x8
            rdi     0x6
            rsi     0xc2081a8db0
            rbp     0xfffffd7fffdff020
            rsp     0xfffffd7fffdfefe8
            r8      0x0
            r9      0x0
            r10     0x0
            r11     0xb14cf0
            r12     0x811a40
            r13     0x717020
            r14     0x0
            r15     0x10
            rip     0xfffffd7fff2da63a
            rflags  0x247
            cs      0x53
            fs      0x0
            gs      0x0
            SIGABRT: used by abort, replace SIGIOT in the future
            PC=0xfffffd7fff2d37a7
            signal arrived during cgo execution
            
            goroutine 22 [runnable]:
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 16 [semacquire]:
            sync.runtime_Semacquire(0xc2080fdf00)
                /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
            sync.(*WaitGroup).Wait(0xc20811ae20)
                /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
            main.(*builder).do(0xc208100000, 0xc208001ee0)
                /home/aram/go/src/cmd/go/build.go:748 +0x440
            main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
                /home/aram/go/src/cmd/go/run.go:115 +0x84f
            main.main()
                /home/aram/go/src/cmd/go/main.go:161 +0x4fa
            
            goroutine 19 [syscall]:
            os/signal.loop()
                /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
            created by os/signal.init·1
                /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
            
            goroutine 21 [select]:
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:729 +0x1a7
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 32 [running]:
                goroutine running on other thread; stack unavailable
            
            rax     0x5b
            rbx     0xfffffd7fff192a40
            rcx     0xfffffd7ffee08000
            rdx     0x0
            rdi     0x0
            rsi     0x0
            rbp     0xfffffd7fffdfef50
            rsp     0xfffffd7fffdfeee8
            r8      0xfffffd7ffef99140
            r9      0x40
            r10     0xfffffd7ffee08000
            r11     0x286
            r12     0xb32280
            r13     0xfffffd7fff34ca00
            r14     0x0
            r15     0x0
            rip     0xfffffd7fff2d37a7
            rflags  0x247
            cs      0x53
            fs      0x0
            gs      0x0
            
            
            wanted:
            main: recovered done
            new-thread: recovered done
            second-new-thread: recovered done
            main-again: recovered done

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 8:

I had this program deadlock too:
    package main
    
    import (
        "fmt"
    )
    
    func main() {
        func() {
            defer func() {
                fmt.Println(recover())
            }()
            var x [8192]byte
            func(x [8192]byte) {
                defer func() {
                    if err := recover(); err != nil {
                        panic("wrap: " + err.(string))
                    }
                }()
                panic("bad")
            }(x)
        }()
        panic("again")
    }
With this crashdump (actually there are two crashdumps here):
--- FAIL: TestRecursivePanic-4 (35.13 seconds)
    crash_test.go:142: output does not start with "wrap: bad\npanic: again\n\n":
        SIGABRT: used by abort, replace SIGIOT in the future
        PC=0xfffffd7fff2da63a
        signal arrived during cgo execution
        
        goroutine 21 [syscall]:
        runtime.cgocall(0x4849f0, 0xc2081aec98)
            /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xc2081aec88
        syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc2081aedb0, 0x8, ...)
            /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xc2081aecd0
        syscall.readlen(0x6, 0xc2081aedb0, 0x8, 0x9, 0x0, ...)
            /home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa fp=0xc2081aed38
        syscall.forkExec(0xc20818bf80, 0x27, 0xc2081aa780, 0x8, 0x8, ...)
            /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8 fp=0xc2081aee68
        syscall.StartProcess(0xc20818bf80, 0x27, 0xc2081aa780, 0x8, 0x8, ...)
            /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc2081aeeb8
        os.startProcess(0xc20818bf80, 0x27, 0xc2081aa780, 0x8, 0x8, ...)
            /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc2081aefe0
        os.StartProcess(0xc20818bf80, 0x27, 0xc2081aa780, 0x8, 0x8, ...)
            /home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc2081af030
        os/exec.(*Cmd).Start(0xc2080d1cc0, 0x0, 0x0)
            /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc2081af1d0
        os/exec.(*Cmd).Run(0xc2080d1cc0, 0x0, 0x0)
            /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc2081af200
        main.(*builder).runOut(0xc208102000, 0x825df0, 0x1, 0x865b50, 0x16, ...)
            /home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc2081af318
        main.(*builder).run(0xc208102000, 0x825df0, 0x1, 0x865b50, 0x16, ...)
            /home/aram/go/src/cmd/go/build.go:1325 +0xe6 fp=0xc2081af410
        main.gcToolchain.ld(0xc208102000, 0xc20806e000, 0xc2080f1bc0, 0x3b, 0xc2081aa600, ...)
            /home/aram/go/src/cmd/go/build.go:1775 +0x1091 fp=0xc2081af6b0
        main.gcToolchain.ld·i(0x0, 0xc208102000, 0xc20806e000, 0xc2080f1bc0, 0x3b, ...)
            /home/aram/go/src/cmd/go/build.go:1 +0xe3 fp=0xc2081af728
        main.(*builder).build(0xc208102000, 0xc2080001a0, 0x0, 0x0)
            /home/aram/go/src/cmd/go/build.go:999 +0x3825 fp=0xc2081afea8
        main.func·005(0xc2080001a0)
            /home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc2081aff50
        main.func·006()
            /home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc2081affa8
        runtime.goexit()
            /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc2081affb0
        created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
        
        goroutine 16 [semacquire]:
        sync.runtime_Semacquire(0xc2080fdd00)
            /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
        sync.(*WaitGroup).Wait(0xc20818d040)
            /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
        main.(*builder).do(0xc208102000, 0xc208001ad0)
            /home/aram/go/src/cmd/go/build.go:748 +0x440
        main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
            /home/aram/go/src/cmd/go/run.go:115 +0x84f
        main.main()
            /home/aram/go/src/cmd/go/main.go:161 +0x4fa
        
        goroutine 19 [syscall]:
        os/signal.loop()
            /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
        created by os/signal.init·1
            /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
        
        goroutine 22 [select]:
        main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
        created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
        
        goroutine 32 [finalizer wait]:
        runtime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)
            /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
        runtime.parkunlock(0xb10ec0, 0xb0e6b5)
            /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
        runfinq()
            /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
        runtime.goexit()
            /home/aram/go/src/pkg/runtime/proc.c:1448
        
        rax     0x5b
        rbx     0xfffffd7fff192a40
        rcx     0x0
        rdx     0x8
        rdi     0x6
        rsi     0xc2081aedb0
        rbp     0xfffffd7fffdff020
        rsp     0xfffffd7fffdfefe8
        r8      0x0
        r9      0x0
        r10     0x0
        r11     0xb14cf0
        r12     0x811a40
        r13     0x717020
        r14     0x0
        r15     0x10
        rip     0xfffffd7fff2da63a
        rflags  0x247
        cs      0x53
        fs      0x0
        gs      0x0
        SIGABRT: used by abort, replace SIGIOT in the future
        PC=0xfffffd7fff2d37a7
        signal arrived during cgo execution
        
        goroutine 21 [runnable]:
        created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
        
        goroutine 16 [semacquire]:
        sync.runtime_Semacquire(0xc2080fdd00)
            /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
        sync.(*WaitGroup).Wait(0xc20818d040)
            /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
        main.(*builder).do(0xc208102000, 0xc208001ad0)
            /home/aram/go/src/cmd/go/build.go:748 +0x440
        main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
            /home/aram/go/src/cmd/go/run.go:115 +0x84f
        main.main()
            /home/aram/go/src/cmd/go/main.go:161 +0x4fa
        
        goroutine 19 [syscall]:
        os/signal.loop()
            /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
        created by os/signal.init·1
            /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
        
        goroutine 22 [select]:
        main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
        created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
        
        goroutine 32 [running]:
            goroutine running on other thread; stack unavailable
        
        rax     0x5b
        rbx     0xfffffd7fff192a40
        rcx     0xfffffd7ffedff000
        rdx     0x0
        rdi     0x0
        rsi     0x0
        rbp     0xfffffd7fffdfef50
        rsp     0xfffffd7fffdfeee8
        r8      0xfffffd7ffefa7140
        r9      0x3a
        r10     0xfffffd7ffedff000
        r11     0x286
        r12     0xb32280
        r13     0xfffffd7fff34ca00
        r14     0x0
        r15     0x0
        rip     0xfffffd7fff2d37a7
        rflags  0x247
        cs      0x53
        fs      0x0
        gs      0x0

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 9:

In all cases it seems to be go command, not the test itself.
There seems always to be:
    goroutine 32 [running]:
        goroutine running on other thread; stack unavailable
but no goroutine creation frame.
Please collect crash reports with GOTRACEBACK=2 env var, it should show goroutine
creation frame.

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 10:

Darn, I forgot about GOTRACEBACK=2, I usually have GOTRACEBACK=crash in
my .profile, but not on this test machine.
This is go test deadlocking again before trying any test. We have two
go test processes:
      6840 pts/1    S  0:00 go test -v -short -cpu=1,2,4 runtime
      6890 pts/1    S  0:00 go test -v -short -cpu=1,2,4 runtime
They have no children.
We send a signal to one of them:
    ; kill -SIGABRT 6840
We get this crashdump:
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2da63a
    signal arrived during cgo execution
    
    goroutine 22 [syscall]:
    runtime.cgocall(0x4849f0, 0xc20846adb0)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xc20846ada0
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc20846aec8, 0x8, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xc20846ade8
    syscall.readlen(0x6, 0xc20846aec8, 0x8, 0xb, 0x0, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa fp=0xc20846ae50
    syscall.forkExec(0xc208502930, 0x27, 0xc208434320, 0xa, 0xa, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8 fp=0xc20846af80
    syscall.StartProcess(0xc208502930, 0x27, 0xc208434320, 0xa, 0xa, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc20846afd0
    os.startProcess(0xc208502930, 0x27, 0xc208434320, 0xa, 0xa, ...)
        /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc20846b0f8
    os.StartProcess(0xc208502930, 0x27, 0xc208434320, 0xa, 0xa, ...)
        /home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc20846b148
    os/exec.(*Cmd).Start(0xc2084eb2c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc20846b2e8
    os/exec.(*Cmd).Run(0xc2084eb2c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc20846b318
    main.(*builder).runOut(0xc2080fe070, 0xc208054980, 0x1d, 0xfffffd7fffdff35d, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc20846b430
    main.(*builder).run(0xc2080fe070, 0xc208054980, 0x1d, 0xfffffd7fffdff35d, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1325 +0xe6 fp=0xc20846b528
    main.gcToolchain.asm(0xc2080fe070, 0xc208112c00, 0xc208459080, 0x2f, 0xc2084fe600, ...)
        /home/aram/go/src/cmd/go/build.go:1610 +0x4d3 fp=0xc20846b6d0
    main.gcToolchain.asm·i(0x0, 0xc2080fe070, 0xc208112c00, 0xc208459080, 0x2f, ...)
        /home/aram/go/src/cmd/go/build.go:1 +0xa3 fp=0xc20846b728
    main.(*builder).build(0xc2080fe070, 0xc208420dd0, 0x0, 0x0)
        /home/aram/go/src/cmd/go/build.go:965 +0x3057 fp=0xc20846bea8
    main.func·005(0xc208420dd0)
        /home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc20846bf50
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc20846bfa8
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc20846bfb0
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire, 2 minutes]:
    runtime.park(0x46cb70, 0xb1cfc0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb1cfc0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runtime.semacquire(0xc2084304e8, 0x1)
        /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
    sync.runtime_Semacquire(0xc2084304e8)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208452e80)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc2080fe070, 0xc20845d040)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x4, 0x4)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 19 [syscall, 2 minutes]:
    runtime.notetsleepg(0xb12ce0, 0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.signal_recv(0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 21 [select, 2 minutes]:
    runtime.park(0x475e20, 0xc2084620c0, 0xb0b767)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    selectgo(0xfffffd7ffefbcf50)
        /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
    runtime.selectgo(0xc2084620c0)
        /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 80 [finalizer wait, 2 minutes]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e6b5)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0x0
    rdx     0x8
    rdi     0x6
    rsi     0xc20846aec8
    rbp     0xfffffd7fffdff010
    rsp     0xfffffd7fffdfefd8
    r8      0x0
    r9      0x0
    r10     0x0
    r11     0xb14cf0
    r12     0x811a40
    r13     0x0
    r14     0xc208424fc0
    r15     0x10
    rip     0xfffffd7fff2da63a
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
    : oos:go; 
We sent a signal to the other one:
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2d37a7
    signal arrived during cgo execution
    
    goroutine 22 [runnable]:
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire, 4 minutes]:
    runtime.park(0x46cb70, 0xb1cfc0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb1cfc0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runtime.semacquire(0xc2084304e8, 0x1)
        /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
    sync.runtime_Semacquire(0xc2084304e8)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208452e80)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc2080fe070, 0xc20845d040)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x4, 0x4)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall, 4 minutes]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 19 [syscall, 4 minutes]:
    runtime.notetsleepg(0xb12ce0, 0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.signal_recv(0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 21 [select, 4 minutes]:
    runtime.park(0x475e20, 0xc2084620c0, 0xb0b767)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    selectgo(0xfffffd7ffefbcf50)
        /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
    runtime.selectgo(0xc2084620c0)
        /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 80 [running]:
        goroutine running on other thread; stack unavailable
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0xfffffd7ffedff000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7fffdfef40
    rsp     0xfffffd7fffdfeed8
    r8      0xfffffd7ffef9f140
    r9      0x0
    r10     0xfffffd7ffedff000
    r11     0x286
    r12     0xb32280
    r13     0xfffffd7fff34ca00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2d37a7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
This time we're stuck in TestRecursivePanic. We have this process tree
    6941  go test -v -short -cpu=1,2,4 runtime
      6998  /tmp/go-build732110799/runtime/_test/runtime.test -test.v
        7160  go run /tmp/go-build472875536/main.go
          7163  go run /tmp/go-build472875536/main.go
At this point I was not sure if go run actually ran anything and didn't
realize the child was gone, or it just stuck before trying to run anything
the latter seemed more likely. Let's crash the two go run processes.
    ; kill -SIGABRT 7160    # no observable effect
    ; kill -SIGABRT 7163
We get this crashdump, there are two crashdumps in here:
    --- FAIL: TestRecursivePanic-4 (261.70 seconds)
        crash_test.go:142: output does not start with "wrap: bad\npanic: again\n\n":
            SIGABRT: used by abort, replace SIGIOT in the future
            PC=0xfffffd7fff2d37a7
            
            goroutine 0 [idle]:
            
            goroutine 17 [syscall]:
            runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
                /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71 fp=0xfffffd7ffefbff40
            runtime.MHeap_Scavenger()
                /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3 fp=0xfffffd7ffefbffa8
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xfffffd7ffefbffb0
            created by runtime.main
                /home/aram/go/src/pkg/runtime/proc.c:205
            
            goroutine 16 [semacquire, 3 minutes]:
            runtime.park(0x46cb70, 0xb1b880, 0xb08b80)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xb1b880, 0xb08b80)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            runtime.semacquire(0xc208113fc0, 0x1)
                /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
            sync.runtime_Semacquire(0xc208113fc0)
                /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
            sync.(*WaitGroup).Wait(0xc2081ae340)
                /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
            main.(*builder).do(0xc208102000, 0xc2080e9450)
                /home/aram/go/src/cmd/go/build.go:748 +0x440
            main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
                /home/aram/go/src/cmd/go/run.go:115 +0x84f
            main.main()
                /home/aram/go/src/cmd/go/main.go:161 +0x4fa
            runtime.main()
                /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by _rt0_go
                /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
            
            goroutine 18 [GC sweep wait]:
            runtime.park(0x46cb70, 0xb10ec0, 0xb0e4cc)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xb10ec0, 0xb0e4cc)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            bgsweep()
                /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by runtime.gc
                /home/aram/go/src/pkg/runtime/mgc0.c:2178
            
            goroutine 19 [syscall, 3 minutes]:
            runtime.notetsleepg(0xb12ce0, 0xffffffffffffffff)
                /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
            runtime.signal_recv(0xffffffffffffffff)
                /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
            os/signal.loop()
                /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by os/signal.init·1
                /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
            
            goroutine 21 [select, 3 minutes]:
            runtime.park(0x475e20, 0xc208066240, 0xb0b767)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            selectgo(0xfffffd7ffefbdf50)
                /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
            runtime.selectgo(0xc208066240)
                /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:729 +0x1a7
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 22 [syscall]:
            runtime.cgocall(0x4849f0, 0xc208129780)
                /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
            syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x3, 0xc208129898, 0x8, ...)
                /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54
            syscall.readlen(0x3, 0xc208129898, 0x8, 0x2, 0x0, ...)
                /home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa
            syscall.forkExec(0xc20810e440, 0x3b, 0xc208113ff0, 0x1, 0x1, ...)
                /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8
            syscall.StartProcess(0xc20810e440, 0x3b, 0xc208113ff0, 0x1, 0x1, ...)
                /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e
            os.startProcess(0xc20810e440, 0x3b, 0xc208113ff0, 0x1, 0x1, ...)
                /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b
            os.StartProcess(0xc20810e440, 0x3b, 0xc208113ff0, 0x1, 0x1, ...)
                /home/aram/go/src/pkg/os/doc.go:24 +0x76
            os/exec.(*Cmd).Start(0xc2080cfcc0, 0x0, 0x0)
                /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727
            os/exec.(*Cmd).Run(0xc2080cfcc0, 0x0, 0x0)
                /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b
            main.runStdin(0xc208113fe0, 0x1, 0x1)
                /home/aram/go/src/cmd/go/run.go:140 +0x13b
            main.(*builder).runProgram(0xc208102000, 0xc2080e9450, 0x0, 0x0)
                /home/aram/go/src/cmd/go/run.go:129 +0x206
            main.func·005(0xc2080e9450)
                /home/aram/go/src/cmd/go/build.go:682 +0x377
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:739 +0x135
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 23 [chan receive]:
            runtime.park(0x46cb70, 0xc208175550, 0xb0b6cd)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xc208175550, 0xb0b6cd)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            chanrecv(0x70bc20, 0xc208175500, 0x0, 0xc208074401, 0x0)
                /home/aram/go/src/pkg/runtime/chan.goc:266 +0x4e8
            runtime.chanrecv1(0x70bc20, 0xc208175500, 0x0)
                /home/aram/go/src/pkg/runtime/chan.goc:348 +0x38
            main.func·028()
                /home/aram/go/src/cmd/go/signal.go:21 +0x3b
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by main.processSignals
                /home/aram/go/src/cmd/go/signal.go:23 +0xc3
            
            goroutine 34 [finalizer wait, 3 minutes]:
            runtime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xb10ec0, 0xb0e6b5)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            runfinq()
                /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by runtime.gc
                /home/aram/go/src/pkg/runtime/mgc0.c:2178
            
            rax     0x5b
            rbx     0xfffffd7fff192a40
            rcx     0xfffffd7ffef9f000
            rdx     0x0
            rdi     0x0
            rsi     0xfffffd7fffdfefc0
            rbp     0xfffffd7fffdfefb0
            rsp     0xfffffd7fffdfef48
            r8      0xfffffd7ffef99140
            r9      0x76
            r10     0xfffffd7ffef9f000
            r11     0x206
            r12     0xb32280
            r13     0xfffffd7fff34ca00
            r14     0x0
            r15     0xfffffd7fffdfefc0
            rip     0xfffffd7fff2d37a7
            rflags  0x247
            cs      0x53
            fs      0x0
            gs      0x0
            SIGABRT: used by abort, replace SIGIOT in the future
            PC=0xfffffd7fff2d37a7
            signal arrived during cgo execution
            
            goroutine 22 [runnable]:
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 16 [semacquire, 4 minutes]:
            runtime.park(0x46cb70, 0xb1b880, 0xb08b80)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xb1b880, 0xb08b80)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            runtime.semacquire(0xc208113fc0, 0x1)
                /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
            sync.runtime_Semacquire(0xc208113fc0)
                /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
            sync.(*WaitGroup).Wait(0xc2081ae340)
                /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
            main.(*builder).do(0xc208102000, 0xc2080e9450)
                /home/aram/go/src/cmd/go/build.go:748 +0x440
            main.runRun(0xb098c0, 0xc20800c020, 0x1, 0x1)
                /home/aram/go/src/cmd/go/run.go:115 +0x84f
            main.main()
                /home/aram/go/src/cmd/go/main.go:161 +0x4fa
            runtime.main()
                /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by _rt0_go
                /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
            
            goroutine 17 [syscall, 4 minutes]:
            runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
                /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
            runtime.MHeap_Scavenger()
                /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by runtime.main
                /home/aram/go/src/pkg/runtime/proc.c:205
            
            goroutine 18 [GC sweep wait]:
            runtime.park(0x46cb70, 0xb10ec0, 0xb0e4cc)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            runtime.parkunlock(0xb10ec0, 0xb0e4cc)
                /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
            bgsweep()
                /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by runtime.gc
                /home/aram/go/src/pkg/runtime/mgc0.c:2178
            
            goroutine 19 [syscall, 4 minutes]:
            runtime.notetsleepg(0xb12ce0, 0xffffffffffffffff)
                /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
            runtime.signal_recv(0xffffffffffffffff)
                /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
            os/signal.loop()
                /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by os/signal.init·1
                /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
            
            goroutine 21 [select, 4 minutes]:
            runtime.park(0x475e20, 0xc208066240, 0xb0b767)
                /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
            selectgo(0xfffffd7ffefbdf50)
                /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
            runtime.selectgo(0xc208066240)
                /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
            main.func·006()
                /home/aram/go/src/cmd/go/build.go:729 +0x1a7
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by main.(*builder).do
                /home/aram/go/src/cmd/go/build.go:745 +0x416
            
            goroutine 23 [runnable]:
            main.func·028()
                /home/aram/go/src/cmd/go/signal.go:20
            runtime.goexit()
                /home/aram/go/src/pkg/runtime/proc.c:1448
            created by main.processSignals
                /home/aram/go/src/cmd/go/signal.go:23 +0xc3
            
            goroutine 34 [running]:
                goroutine running on other thread; stack unavailable
            created by runtime.gc
                /home/aram/go/src/pkg/runtime/mgc0.c:2178
            
            rax     0x5b
            rbx     0xfffffd7ffef42240
            rcx     0xfffffd7ffee05000
            rdx     0x0
            rdi     0x0
            rsi     0x0
            rbp     0xfffffd7ffddffe70
            rsp     0xfffffd7ffddffe08
            r8      0xfffffd7ffef98140
            r9      0x2e
            r10     0xfffffd7ffee05000
            r11     0x286
            r12     0xb32380
            r13     0xfffffd7fff34ca00
            r14     0x0
            r15     0x0
            rip     0xfffffd7fff2d37a7
            rflags  0x247
            cs      0x53
            fs      0x0
            gs      0x0

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 11:

Let's run
    GOMAXPROCS=2 go test -v -run TestRecursivePanic -cpu=4 runtime
a few times looking at what processes get created. We'll use this
DTrace script:
    dtrace -qn 'proc:::exec-success { printf("%d\t%d\t%s\n", timestamp, pid, curpsinfo->pr_psargs); } syscall::rexit:entry { printf("%d\t%d\texited with: %d\n", timestamp, pid, arg0) }'
Just as a baseline, this is a *successful* run:
    11239490885323  8535    go test -v -run TestRecursivePanic -cpu=4 runtime
    11239728110353  8536    /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build587765460/runtime/_test
    11239866871886  8536    exited with: 0
    11239883466632  8537    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239890801719  8537    exited with: 0
    11239895542510  8538    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239905415455  8538    exited with: 0
    11239910350778  8539    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239919441798  8539    exited with: 0
    11239924290718  8540    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239933657069  8540    exited with: 0
    11239938551321  8541    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239945317341  8541    exited with: 0
    11239950844450  8542    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239961342085  8542    exited with: 0
    11239966190531  8543    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239976905153  8543    exited with: 0
    11239981920318  8544    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11239995104766  8544    exited with: 0
    11240000280632  8545    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240010607513  8545    exited with: 0
    11240015570192  8546    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240024821539  8546    exited with: 0
    11240029644054  8547    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240085795105  8547    exited with: 0
    11240093133002  8548    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240118623717  8548    exited with: 0
    11240124532443  8549    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240135982158  8549    exited with: 0
    11240141171880  8550    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240152069159  8550    exited with: 0
    11240156997962  8551    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240174415564  8551    exited with: 0
    11240179899310  8552    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240195905565  8552    exited with: 0
    11240201286506  8553    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240212493431  8553    exited with: 0
    11240217505230  8554    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240230928404  8554    exited with: 0
    11240236095252  8555    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240291431166  8555    exited with: 0
    11240298762164  8556    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240306422383  8556    exited with: 0
    11240311316196  8557    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240319759929  8557    exited with: 0
    11240324660619  8558    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240337753931  8558    exited with: 0
    11240342947010  8559    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240354688576  8559    exited with: 0
    11240359802330  8560    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240368957524  8560    exited with: 0
    11240373839228  8561    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240398430802  8561    exited with: 0
    11240404236658  8562    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240411802102  8562    exited with: 0
    11240416538798  8563    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240434847080  8563    exited with: 0
    11240441323177  8564    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240461240730  8564    exited with: 0
    11240467414733  8565    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240509520038  8565    exited with: 0
    11240515819528  8566    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240525626264  8566    exited with: 0
    11240530503890  8567    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240545331168  8567    exited with: 0
    11240550781559  8568    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240598402552  8568    exited with: 0
    11240605292255  8569    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240625152826  8569    exited with: 0
    11240630850628  8570    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240638718757  8570    exited with: 0
    11240643471213  8571    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240669087152  8571    exited with: 0
    11240675586422  8572    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240693028791  8572    exited with: 0
    11240698482571  8573    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240715232378  8573    exited with: 0
    11240720654726  8574    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240729490832  8574    exited with: 0
    11240734449982  8575    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240743963136  8575    exited with: 0
    11240748886175  8576    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240760055448  8576    exited with: 0
    11240765158211  8577    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240775182853  8577    exited with: 0
    11240780221213  8578    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240792578987  8578    exited with: 0
    11240803976392  8579    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240822518166  8579    exited with: 0
    11240827995297  8580    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240844118495  8580    exited with: 0
    11240849480103  8581    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240862168790  8581    exited with: 0
    11240867367779  8582    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build587765460/runt
    11240881703829  8582    exited with: 0
    11240887048030  8583    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build587765460/runtime/_test
    11240900925189  8583    exited with: 0
    11240905892647  8584    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build587765460/runtime/_test
    11240910522832  8584    exited with: 0
    11240915019173  8585    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build587765460/runtime/_test
    11240919904183  8585    exited with: 0
    11240924415743  8586    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build587765460/runtime/_test
    11240928651934  8586    exited with: 0
    11240933468011  8587    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build587765460/runtime/_test
    11240939459230  8587    exited with: 0
    11240944068133  8588    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build587765460/runtime/_test
    11240947969085  8588    exited with: 0
    11240956992791  8589    /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build587765460/runtime/_test
    11242513815473  8589    exited with: 0
    11242603913660  8590    /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build587765460/runtime/_test
    11242644576100  8590    exited with: 0
    11242653608175  8591    /home/aram/go/pkg/tool/solaris_amd64/6l -o /tmp/go-build587765460/runtime/_test
    11243449774020  8591    exited with: 0
    11243490218719  8592    /tmp/go-build587765460/runtime/_test/runtime.test -test.v=true -test.run=TestRe
    11243508939808  8593    go list -f {{.Stale}} runtime
    11243558465505  8593    exited with: 0
    11243565752838  8594    go run /tmp/go-build938934377/main.go
    11243672711064  8595    /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build241988125/command-line-
    11243683918998  8595    exited with: 0
    11243688565183  8596    /home/aram/go/pkg/tool/solaris_amd64/6l -o /tmp/go-build241988125/command-line-
    11243939763326  8596    exited with: 0
    11243956101878  8597    /tmp/go-build241988125/command-line-arguments/_obj/exe/main
    11243991360860  8597    exited with: 2
    11243993598393  8594    exited with: 1
    11243997057174  8592    exited with: 0
    11244003155024  8535    exited with: 0
This is an unsuccessful run:
    11371374092361  9086    go test -v -run TestRecursivePanic -cpu=4 runtime
    11371624080252  9087    /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build138564772/runtime/_test
    11371765535236  9087    exited with: 0
    11371782107695  9088    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371789456075  9088    exited with: 0
    11371794230460  9089    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371804049702  9089    exited with: 0
    11371808894052  9090    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371817850986  9090    exited with: 0
    11371822693357  9091    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371832059300  9091    exited with: 0
    11371836854379  9092    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371843608269  9092    exited with: 0
    11371848284831  9093    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371858785161  9093    exited with: 0
    11371863783032  9094    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371874410101  9094    exited with: 0
    11371879300226  9095    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371892520593  9095    exited with: 0
    11371897670814  9096    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371907883943  9096    exited with: 0
    11371912898757  9097    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build138564772/runt
    11371922107079  9097    exited with: 0
It just stops there.
Aha, so the problem is not that the deadlock detector is not working.
Let's try again, we run TestRecursivePanic again, we get this trace:
    11671288231980  9176    go test -v -run TestRecursivePanic -cpu=4 runtime
    11671550871361  9177    /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build400115131/runtime/_test
    11671689422315  9177    exited with: 0
    11671705929221  9178    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671713304099  9178    exited with: 0
    11671718035362  9179    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671727905798  9179    exited with: 0
    11671732743706  9180    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671741689800  9180    exited with: 0
    11671746492255  9181    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671755825030  9181    exited with: 0
    11671760702554  9182    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671767421598  9182    exited with: 0
    11671772063362  9183    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671782528822  9183    exited with: 0
    11671787347126  9184    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671797981031  9184    exited with: 0
    11671802968759  9185    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671816108833  9185    exited with: 0
    11671821211987  9186    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671831509038  9186    exited with: 0
    11671836492418  9187    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671845707560  9187    exited with: 0
    11671850536336  9188    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671906665131  9188    exited with: 0
    11671914124802  9189    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671939809509  9189    exited with: 0
    11671945744582  9190    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671957167238  9190    exited with: 0
    11671962811569  9191    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671973833210  9191    exited with: 0
    11671978821720  9192    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11671996186870  9192    exited with: 0
    11672001651078  9193    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672017610841  9193    exited with: 0
    11672023020409  9194    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672034208920  9194    exited with: 0
    11672039265138  9195    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672052657292  9195    exited with: 0
    11672057793108  9196    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672112894115  9196    exited with: 0
    11672120263748  9197    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672127965989  9197    exited with: 0
    11672132804973  9198    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672141239090  9198    exited with: 0
    11672146120606  9199    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672159121001  9199    exited with: 0
    11672164268782  9200    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672176060081  9200    exited with: 0
    11672181525929  9201    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672190627292  9201    exited with: 0
    11672195534796  9202    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672220056666  9202    exited with: 0
    11672225953273  9203    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672233570019  9203    exited with: 0
    11672238334042  9204    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672251852077  9204    exited with: 0
    11672257080104  9205    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672272790281  9205    exited with: 0
    11672278207266  9206    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672312855001  9206    exited with: 0
    11672319066252  9207    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672327527376  9207    exited with: 0
    11672332363167  9208    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672347075096  9208    exited with: 0
    11672352430274  9209    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672400223999  9209    exited with: 0
    11672407120704  9210    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672426938534  9210    exited with: 0
    11672432564925  9211    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672440467677  9211    exited with: 0
    11672445303648  9212    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672470792277  9212    exited with: 0
    11672476605686  9213    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672494034824  9213    exited with: 0
    11672499501608  9214    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672516163620  9214    exited with: 0
    11672521610099  9215    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672535249705  9215    exited with: 0
    11672542567670  9216    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672552131490  9216    exited with: 0
    11672557074120  9217    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672570937837  9217    exited with: 0
    11672576992125  9218    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672587871671  9218    exited with: 0
    11672593720136  9219    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672608628289  9219    exited with: 0
    11672613771564  9220    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672632768891  9220    exited with: 0
    11672638194413  9221    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672656558264  9221    exited with: 0
    11672662015893  9222    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672677834653  9222    exited with: 0
    11672683324631  9223    /home/aram/go/pkg/tool/solaris_amd64/6c -F -V -w -I /tmp/go-build400115131/runt
    11672697577802  9223    exited with: 0
    11672702916612  9224    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build400115131/runtime/_test
    11672716731508  9224    exited with: 0
    11672721744239  9225    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build400115131/runtime/_test
    11672726307283  9225    exited with: 0
    11672730811563  9226    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build400115131/runtime/_test
    11672735687085  9226    exited with: 0
    11672740298882  9227    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build400115131/runtime/_test
    11672744547022  9227    exited with: 0
    11672749106812  9228    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build400115131/runtime/_test
    11672755161624  9228    exited with: 0
    11672759803069  9229    /home/aram/go/pkg/tool/solaris_amd64/6a -I /tmp/go-build400115131/runtime/_test
    11672763726150  9229    exited with: 0
This time it stopped at a different point, let's crash the two go test
processes:
    9176  go test -v -run TestRecursivePanic -cpu=4 runtime
    9230  go test -v -run TestRecursivePanic -cpu=4 runtime
    ; kill -SIGABRT 9176
    ; kill -SIGABRT 9230
We get this crashdumps (again, there are two crashdumps in here):
    SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2d37a7
    
    goroutine 0 [idle]:
    
    goroutine 16 [semacquire, 1 minutes]:
    runtime.park(0x46cb70, 0xb1b3c0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb1b3c0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runtime.semacquire(0xc208435f88, 0x1)
        /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
    sync.runtime_Semacquire(0xc208435f88)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208458a60)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc2081060e0, 0xc20845e9c0)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x5, 0x5)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 19 [syscall, 1 minutes]:
    runtime.notetsleepg(0xb12ce0, 0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.signal_recv(0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 20 [syscall]:
    runtime.cgocall(0x4849f0, 0xc20846cdf0)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc20846cf08, 0x8, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54
    syscall.readlen(0x6, 0xc20846cf08, 0x8, 0x24, 0x0, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:517 +0xaa
    syscall.forkExec(0xc208462ae0, 0x27, 0xc208448fc0, 0x23, 0x24, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8
    syscall.StartProcess(0xc208462ae0, 0x27, 0xc208448fc0, 0x23, 0x24, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e
    os.startProcess(0xc208462ae0, 0x27, 0xc208448fc0, 0x23, 0x24, ...)
        /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b
    os.StartProcess(0xc208462ae0, 0x27, 0xc208448fc0, 0x23, 0x24, ...)
        /home/aram/go/src/pkg/os/doc.go:24 +0x76
    os/exec.(*Cmd).Start(0xc208468140, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727
    os/exec.(*Cmd).Run(0xc208468140, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b
    main.(*builder).runOut(0xc2081060e0, 0xc2080549a0, 0x1d, 0xc2080d5ab0, 0xc, ...)
        /home/aram/go/src/cmd/go/build.go:1374 +0x298
    main.gcToolchain.gc(0xc2081060e0, 0xc20811e800, 0xc208437780, 0x33, 0xc20845aa50, ...)
        /home/aram/go/src/cmd/go/build.go:1604 +0xced
    main.gcToolchain.gc·i(0x0, 0xc2081060e0, 0xc20811e800, 0xc208437780, 0x33, ...)
        /home/aram/go/src/cmd/go/build.go:1 +0x181
    main.(*builder).build(0xc2081060e0, 0xc20842ca90, 0x0, 0x0)
        /home/aram/go/src/cmd/go/build.go:907 +0x229a
    main.func·005(0xc20842ca90)
        /home/aram/go/src/cmd/go/build.go:682 +0x377
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:739 +0x135
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 21 [select]:
    runtime.park(0x475e20, 0xc2084640c0, 0xb0b767)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    selectgo(0xfffffd7ffefbcf50)
        /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
    runtime.selectgo(0xc2084640c0)
        /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 33 [finalizer wait, 1 minutes]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e6b5)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e6b5)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2555 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0xfffffd7ffefae000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7fffdfeec0
    rsp     0xfffffd7fffdfee58
    r8      0xfffffd7ffefa8140
    r9      0x76
    r10     0xfffffd7ffefae000
    r11     0xfffffffffbc05668
    r12     0xb32280
    r13     0xfffffd7fff34ca00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2d37a7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
    : oos:go; SIGABRT: used by abort, replace SIGIOT in the future
    PC=0xfffffd7fff2d37a7
    signal arrived during cgo execution
    
    goroutine 20 [runnable]:
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire, 1 minutes]:
    runtime.park(0x46cb70, 0xb1b3c0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb1b3c0, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runtime.semacquire(0xc208435f88, 0x1)
        /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
    sync.runtime_Semacquire(0xc208435f88)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208458a60)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc2081060e0, 0xc20845e9c0)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x5, 0x5)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall, 1 minutes]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x46cb70, 0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ec0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1907 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    goroutine 19 [syscall, 1 minutes]:
    runtime.notetsleepg(0xb12ce0, 0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.signal_recv(0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 21 [runnable]:
    runtime.park(0x475e20, 0xc2084640c0, 0xb0b767)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    selectgo(0xfffffd7ffefbcf50)
        /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
    runtime.selectgo(0xc2084640c0)
        /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 33 [running]:
        goroutine running on other thread; stack unavailable
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2178
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0xfffffd7ffee03000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7fffdfef20
    rsp     0xfffffd7fffdfeeb8
    r8      0xfffffd7ffefa8140
    r9      0x0
    r10     0xfffffd7ffee03000
    r11     0x286
    r12     0xb32280
    r13     0xfffffd7fff34ca00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2d37a7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 12:

I see that bgsweep creates a goroutine, I don't see it in the crash. It
should be running runfinq, which I can't find in any stack traces. It
couldn't have finished already because runfinq eventually unparks
bgsweep. Any idea why it's not there?

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 13:

I do see runfinq in another stack trace though:
goroutine 48 [finalizer wait]:
runtime.park(0x46d1d0, 0xb10ea0, 0xb0e6b2)
    /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
runtime.parkunlock(0xb10ea0, 0xb0e6b2)
    /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
runfinq()
    /home/aram/go/src/pkg/runtime/mgc0.c:2556 +0xc2
runtime.goexit()
    /home/aram/go/src/pkg/runtime/proc.c:1448
created by runtime.gc
    /home/aram/go/src/pkg/runtime/mgc0.c:2179
I guess this was the problem in the other case
goroutine 48 [running]:
    goroutine running on other thread; stack unavailable
created by runtime.gc
    /home/aram/go/src/pkg/runtime/mgc0.c:2179

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 14:

Could it be partially related to issue #7375?
In the last trace, the goroutine is stuck in finalizer wait state. Some
people complained *today* in #go-nuts about:
   mfinal_test.go:100: finalizer for type *bigValue didn't run
If the finalizers don't run, then that goroutine is stuck there forever
and can't get the chance to unpark the bgsweep goroutine.
Yes, this is purportedly fixed by 67850044, but people still see it
(including myself)

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 15:

runfinq does not unpark bgsweep, it's the other way around

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 16:

Yes, I've realized that after I posted here.

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 17:

Yes, I've realized that after I posted here and read the code better.

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 18:

how much CPU does the process consume? I am curious whether it is an infinite loop or
deadlocked. Any chance of attaching a debugger and obtaining trace from the runfinq (or
at least sampling of current PCs)?

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 19:

It doesn't use any CPU because all threads are parked.
     15420 pts/1    S  0:00 go test -v -run TestRecursivePanic -cpu=4 runtime
     15476 pts/1    S  0:00 go test -v -run TestRecursivePanic -cpu=4 runtime
     
     : oos:aram; pstack 15420
    15420:  go test -v -run TestRecursivePanic -cpu=4 runtime
    -----------------  lwp# 1 / thread# 1  --------------------
     fffffd7fff2da63a read     (6, c208464db0, 8)
     0000000000485180 runtime.asmsysvicall6 () + 50
     000000c208464c08 ???????? ()
     fffffd7fffdff050 ???????? ()
    -----------------  lwp# 2 / thread# 2  --------------------
     fffffd7fff2d37a7 lwp_park (0, 0, 0)
     fffffd7fff2c5f33 sema_wait (b322e0) + 13
     fffffd7fff2ba728 sem_wait (b322e0) + 38
     0000000000485180 runtime.asmsysvicall6 () + 50
     0000000000000000 ???????? ()
     fffffd7ffedfffb8 ???????? ()
    -----------------  lwp# 3 / thread# 3  --------------------
     fffffd7fff2d37a7 lwp_park (0, fffffd7ffe9ffef0, 0)
     fffffd7fff2c5f68 sema_reltimedwait (b32220, c208016940) + 28
     fffffd7fff2ba80b sem_reltimedwait_np (b32220, c208016940) + 4b
     0000000000485180 runtime.asmsysvicall6 () + 50
     0000000000000000 ???????? ()
     fffffd7ffe9fffb8 ???????? ()
    -----------------  lwp# 4 / thread# 4  --------------------
     fffffd7fff2d37a7 lwp_park (0, 0, 0)
     fffffd7fff2c5f33 sema_wait (b322a0) + 13
     fffffd7fff2ba728 sem_wait (b322a0) + 38
     0000000000485180 runtime.asmsysvicall6 () + 50
     0000000000000000 ???????? ()
     fffffd7ffe5fffb8 ???????? ()
    -----------------  lwp# 5 / thread# 5  --------------------
     fffffd7fff2d37a7 lwp_park (0, 0, 0)
     fffffd7fff2c5f33 sema_wait (b32320) + 13
     fffffd7fff2ba728 sem_wait (b32320) + 38
     0000000000485180 runtime.asmsysvicall6 () + 50
     fffffd7ffeb22bb8 ???????? ()
     fffffd7ffe1fffb8 ???????? ()
    -----------------  lwp# 6 / thread# 6  --------------------
     fffffd7fff2d37a7 lwp_park (0, 0, 0)
     fffffd7fff2c5f33 sema_wait (b32360) + 13
     fffffd7fff2ba728 sem_wait (b32360) + 38
     0000000000485180 runtime.asmsysvicall6 () + 50
     fffffd7ffeb02bb8 ???????? ()
     fffffd7ffddfffb8 ???????? ()
    -----------------  lwp# 7 / thread# 7  --------------------
     fffffd7fff2d37a7 lwp_park (0, 0, 0)
     fffffd7fff2c5f33 sema_wait (b323a0) + 13
     fffffd7fff2ba728 sem_wait (b323a0) + 38
     0000000000485180 runtime.asmsysvicall6 () + 50
     0000000000000000 ???????? ()
     fffffd7ffd9fffb8 ???????? ()
     
    : oos:aram; pstack 15476
    15476:  go test -v -run TestRecursivePanic -cpu=4 runtime
     fffffd7fff2d37a7 lwp_park (0, 0, 0)
     fffffd7fff2c5f33 sema_wait (b32260) + 13
     fffffd7fff2ba728 sem_wait (b32260) + 38
     0000000000485180 runtime.asmsysvicall6 () + 50
     000000c208464c48 ???????? ()
     fffffd7fffdff050 ???????? ()
Yes, I can attach a debugger if you want me to give any other info.

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 20:

I confirm again that disabling the GC fixes the problem.

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 21:

I am out of ideas.
If you insert printf's into runfinq, we could be able to understand on what statement it
hangs...

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 22:

It's this, isn't it?
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2556 +0xc2
    for(;;) {
        runtime·lock(&gclock);
        fb = finq;
        finq = nil;
        if(fb == nil) {
            fingwait = 1;
>>>         runtime·parkunlock(&gclock, "finalizer wait");
            continue;
        }
The runtime·parkunlock call.

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 23:

after parkunlock the goroutine must not be in "running" state

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 24:

In the stack trace I pasted above, it's in running state, but in most
stacktraces, it seems to be in finalizer wait state. Here is another
stack trace.
    PC=0xfffffd7fff2da63a
    signal arrived during cgo execution
    
    goroutine 22 [syscall]:
    runtime.cgocall(0x485130, 0xc208482c58)
        /home/aram/go/src/pkg/runtime/cgocall.c:152 +0x10a fp=0xc208482c48
    syscall.sysvicall6(0xfffffd7fff2c2d00, 0x3, 0x6, 0xc208482d70, 0x8, ...)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:65 +0x54 fp=0xc208482c90
    syscall.readlen(0x6, 0xc208482d70, 0x8, 0x10, 0x0, ...)
        /home/aram/go/src/pkg/syscall/syscall_solaris.go:495 +0xaa fp=0xc208482cf8
    syscall.forkExec(0xc2084c0c00, 0x27, 0xc208455a40, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:200 +0x5b8 fp=0xc208482e28
    syscall.StartProcess(0xc2084c0c00, 0x27, 0xc208455a40, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc208482e78
    os.startProcess(0xc2084c0c00, 0x27, 0xc208455a40, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc208482fa0
    os.StartProcess(0xc2084c0c00, 0x27, 0xc208455a40, 0xf, 0xf, ...)
        /home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc208482ff0
    os/exec.(*Cmd).Start(0xc2084c43c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc208483190
    os/exec.(*Cmd).Run(0xc2084c43c0, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc2084831c0
    main.(*builder).runOut(0xc2081020e0, 0xc2080d4680, 0x1d, 0xfffffd7fffdff342, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc2084832d8
    main.(*builder).run(0xc2081020e0, 0xc2080d4680, 0x1d, 0xfffffd7fffdff342, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1325 +0xe6 fp=0xc2084833d0
    main.gcToolchain.cc(0xc2081020e0, 0xc208101800, 0xc208469800, 0x2f, 0xc2084853c0, ...)
        /home/aram/go/src/cmd/go/build.go:1782 +0x949 fp=0xc2084836d0
    main.gcToolchain.cc·i(0x0, 0xc2081020e0, 0xc208101800, 0xc208469800, 0x2f, ...)
        /home/aram/go/src/cmd/go/build.go:1 +0xa3 fp=0xc208483728
    main.(*builder).build(0xc2081020e0, 0xc2084400d0, 0x0, 0x0)
        /home/aram/go/src/cmd/go/build.go:956 +0x2ce8 fp=0xc208483ea8
    main.func·005(0xc2084400d0)
        /home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc208483f50
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc208483fa8
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc208483fb0
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire]:
    runtime.park(0x46d1d0, 0xb1cf60, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb1cf60, 0xb08b80)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runtime.semacquire(0xc2084465d8, 0x1)
        /home/aram/go/src/pkg/runtime/sema.goc:140 +0x10e
    sync.runtime_Semacquire(0xc2084465d8)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc208470980)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc2081020e0, 0xc208474270)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x5, 0x5)
        /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    runtime.main()
        /home/aram/go/src/pkg/runtime/proc.c:245 +0x11a
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by _rt0_go
        /home/aram/go/src/pkg/runtime/asm_amd64.s:97 +0x132
    
    goroutine 17 [syscall]:
    runtime.notetsleepg(0xfffffd7ffefbff68, 0xdf8475800)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.MHeap_Scavenger()
        /home/aram/go/src/pkg/runtime/mheap.c:531 +0xa3
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.main
        /home/aram/go/src/pkg/runtime/proc.c:205
    
    goroutine 18 [GC sweep wait]:
    runtime.park(0x46d1d0, 0xb10ea0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ea0, 0xb0e4cc)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    bgsweep()
        /home/aram/go/src/pkg/runtime/mgc0.c:1910 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2179
    
    goroutine 19 [syscall]:
    runtime.notetsleepg(0xb12cc0, 0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/lock_sema.c:263 +0x71
    runtime.signal_recv(0xffffffffffffffff)
        /home/aram/go/src/pkg/runtime/sigqueue.goc:110 +0xe2
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 21 [select]:
    runtime.park(0x476560, 0xc2084780c0, 0xb0b767)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    selectgo(0xfffffd7ffefbcf50)
        /home/aram/go/src/pkg/runtime/chan.goc:800 +0x3a0
    runtime.selectgo(0xc2084780c0)
        /home/aram/go/src/pkg/runtime/chan.goc:643 +0x12
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 48 [finalizer wait]:
    runtime.park(0x46d1d0, 0xb10ea0, 0xb0e6b2)
        /home/aram/go/src/pkg/runtime/proc.c:1372 +0x89
    runtime.parkunlock(0xb10ea0, 0xb0e6b2)
        /home/aram/go/src/pkg/runtime/proc.c:1388 +0x3b
    runfinq()
        /home/aram/go/src/pkg/runtime/mgc0.c:2556 +0xc2
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448
    created by runtime.gc
        /home/aram/go/src/pkg/runtime/mgc0.c:2179
    
    rax     0x5b
    rbx     0xfffffd7fff192a40
    rcx     0x0
    rdx     0x8
    rdi     0x6
    rsi     0xc208482d70
    rbp     0xfffffd7fffdfefe0
    rsp     0xfffffd7fffdfefa8
    r8      0x0
    r9      0x0
    r10     0x0
    r11     0xb14cd0
    r12     0x811c00
    r13     0x0
    r14     0xc208439040
    r15     0x10
    rip     0xfffffd7fff2da63a
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0

@dvyukov
Copy link
Member

dvyukov commented Mar 12, 2014

Comment 25:

I have a hypothesis that forkAndExecInChild in exec_solaris.go makes some allocations or
calls some other prohibited function after:
    // About to call fork.
    // No more allocation or calls of non-assembly functions.
The hypothesis is that the process forks with gclock locked, that's why runfinq hangs.

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 26:

I thought of that too, I checked it and it doesn't seem the case. I'll check it again.

@4ad
Copy link
Member Author

4ad commented Mar 12, 2014

Comment 27:

Nope, all functions are NOSPLIT.

@rsc
Copy link
Contributor

rsc commented Mar 13, 2014

Comment 28:

Why is forkExec blocked in a system call?

Status changed to Accepted.

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 29:

I don't know, it's stuck in the readlen (read) call. There are the
(interesting) files in the parent:
   4: S_IFIFO mode:0000 dev:532,0 ino:62757399 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
   5: S_IFIFO mode:0000 dev:532,0 ino:62757399 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
   6: S_IFIFO mode:0000 dev:532,0 ino:62757400 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
And these are the interesting files in the child:
      
   4: S_IFIFO mode:0000 dev:532,0 ino:62757399 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
   5: S_IFIFO mode:0000 dev:532,0 ino:62757399 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
   6: S_IFIFO mode:0000 dev:532,0 ino:62757400 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
   7: S_IFIFO mode:0000 dev:532,0 ino:62757400 uid:1000 gid:10 rdev:0,0
      O_RDWR FD_CLOEXEC
The parent is reading from file descriptor 6. You can see it's close
on exec.

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 30:

Btw, with GOMAXPROCS=1 it works (even with -cpu 4), only GOMAXPROCS=2 makes it fail (so
GOMAXPROCS=2 in run.bash was a good idea after all).

@rsc
Copy link
Contributor

rsc commented Mar 13, 2014

Comment 31:

the child does exec, which closes the fds on success, and then on failure
the child writes an error code to the fd and exits (which closes the fds).
so either the exec is blocking or the write is blocking. why is the child
blocked?

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 32:

Exec completes successfuly and doesn't block (at least that's what
DTrace says). The child is stuck in lwp_park, which comes from
sem_wait, which is called from runtime·semasleep. The child goes a
long way in its life until things go haywire. This is the supposed
stack of the child:
    PC=0xfffffd7fff2bf7c7
    signal arrived during cgo execution
    
    goroutine 21 [runnable]:
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire]:
    sync.runtime_Semacquire(0xc208445148)
            /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc20845b260)
            /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc2080fe0e0, 0xc20846bba0)
            /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runTest(0xb09960, 0xc20800c020, 0x5, 0x5)
            /home/aram/go/src/cmd/go/test.go:512 +0x25bf
    main.main()
            /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    
    goroutine 19 [syscall]:
    os/signal.loop()
            /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    created by os/signal.init·1
            /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 49 [running]:
            goroutine running on other thread; stack unavailable
    
    goroutine 22 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 23 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 24 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 25 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 26 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 27 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 28 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 29 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 30 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 31 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 32 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 33 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 34 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 35 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 36 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 37 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 38 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 39 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 40 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 41 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 42 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 43 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 44 [select]:
    main.func·006()
            /home/aram/go/src/cmd/go/build.go:729 +0x1a7
    created by main.(*builder).do
            /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    rax     0x5b
    rbx     0xfffffd7ffef41a40
    rcx     0xfffffd7fff35a000
    rdx     0x0
    rdi     0x0
    rsi     0x0
    rbp     0xfffffd7ffe1ffe70
    rsp     0xfffffd7ffe1ffe08
    r8      0xfffffd7ffef99d40
    r9      0x76
    r10     0xfffffd7fff35a000
    r11     0x286
    r12     0xb32340
    r13     0xfffffd7fff338a00
    r14     0x0
    r15     0x0
    rip     0xfffffd7fff2bf7c7
    rflags  0x247
    cs      0x53
    fs      0x0
    gs      0x0
But I don't believe this stack trace. It says:
    goroutine 49 [running]:
            goroutine running on other thread; stack unavailable
There is only one thread and there is nothing running.

@rsc
Copy link
Contributor

rsc commented Mar 13, 2014

Comment 33:

if exec completed successfully why did the close-on-exec file descriptors
not get closed?

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 34:

I don't know, maybe it's a kernel bug, investigating...

@dvyukov
Copy link
Member

dvyukov commented Mar 13, 2014

Comment 35:

My suspicion was that the child has not forked yet, but tried lock gclock, which is
locked in child.
You always post traces from 2 processes, what are these processes? Is it 2 equivalent
processes, or parent and child?
In #19 you've posted debugger thread dump. One process contains several threads, which
is normal for Go process. But the other one contains only 1 thread, which can't happen
in a running Go process. Maybe it's a forked-but-not-execed child? Note that SIGABRT in
such process can still print several goroutines (and some of them can be running), but
that is just what left in memory from parent.

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 36:

> My suspicion was that the child has not forked yet, but tried
> lock gclock, which is locked in child.
You mean the child has not exec'ed yet, but tried to lock gclock
which is locked in *parent*?
> You always post traces from 2 processes, what are these processes?
> Is it 2 equivalent processes, or parent and child?
Parent and child. They have the same argv, so it seems exec didn't
happen yet.
> In #19 you've posted debugger thread dump. One process contains
> several threads, which is normal for Go process. But the other one
> contains only 1 thread, which can't happen in a running Go process.
> Maybe it's a forked-but-not-execed child?
I think so, yes.
> Note that SIGABRT in such process can still print several goroutines
> (and some of them can be running), but that is just what left in
> memory from parent.
Makes sense.
What could trigger a GC in the child then? All variables are declared
beforehand, and all functions are NOSPLIT (I'll check again, a third
time). The NOSPLIT functions call asmcgocall, however, could that
have anything to do with it?

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 37:

> if exec completed successfully why did the close-on-exec file
> descriptors not get closed?
I believe I observed a different successful exec. When it hangs,
it doesn't reach exec.

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 38:

Yep, we see a fork and no exec.
    dtrace -qn 'proc:::exec-success { printf("%d\t%d\texec %s\n", timestamp, pid, curpsinfo->pr_psargs) } syscall::*fork*:entry { printf("%d\t%d\t%s\n", timestamp, pid, probefunc); }'
    395699329518    3783    forksys
    395701606107    3784    exec go list -f {{.Stale}} runtime
    395755849307    3783    forksys
    395757659031    3785    exec go run /tmp/go-build862821276/main.go
    395867980642    3785    forksys
    395870653159    3786    exec /home/aram/go/pkg/tool/solaris_amd64/6g -o /tmp/go-build051016717/command-line-
    395883945224    3785    forksys
    395886146342    3787    exec /home/aram/go/pkg/tool/solaris_amd64/6l -o /tmp/go-build051016717/command-line-
    396152174359    3785    forksys

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 39:

I think I fixed it.
I used by mistake runtime·cgocall instead of runtime·asmcgocall in
one syscall_solaris.goc function.
Thanks everyone.

@dvyukov
Copy link
Member

dvyukov commented Mar 13, 2014

Comment 40:

>You mean the child has not exec'ed yet, but tried to lock gclock which is locked in
*parent*?
Yes, that's what I meant. Sorry.
>What could trigger a GC in the child then?
The most likely causes are implicit call to malloc (some var escapes) or a call to
not-NOSPLIT function.
Try to clpatch:
https://golang.org/cl/75260043
it must detect this situation.

@4ad
Copy link
Member Author

4ad commented Mar 13, 2014

Comment 41:

Yes, it detected it beautifully, thanks:
    fatal error: split stack after fork
    
    runtime stack:
    runtime.throw(0x851fdf)
        /home/aram/go/src/pkg/runtime/panic.c:496 +0x69
    runtime.newstack()
        /home/aram/go/src/pkg/runtime/stack.c:587 +0x48
    runtime.morestack()
        /home/aram/go/src/pkg/runtime/asm_amd64.s:228 +0x6a
    
    goroutine 21 [running]:
    runtime.cgocall(0x474900, 0xc208176db0)
        /home/aram/go/src/pkg/runtime/cgocall.c:98 +0x13 fp=0xc208176da0
    syscall.fcntl1(0x3, 0x9, 0x0, 0xc2081d2f80, 0x3)
        /home/aram/go/src/pkg/runtime/syscall_solaris.goc:196 +0x3c fp=0xc208176de8
    syscall.forkAndExecInChild(0xc2081a7710, 0xc208051740, 0x18, 0x18, 0xc2081c1500, ...)
        /home/aram/go/src/pkg/syscall/exec_solaris.go:187 +0x6df fp=0xc208176e90
    syscall.forkExec(0xc2081a71d0, 0x27, 0xc2081c1380, 0x17, 0x18, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:191 +0x500 fp=0xc208176fc0
    syscall.StartProcess(0xc2081a71d0, 0x27, 0xc2081c1380, 0x17, 0x18, ...)
        /home/aram/go/src/pkg/syscall/exec_unix.go:238 +0x8e fp=0xc208177010
    os.startProcess(0xc2081a71d0, 0x27, 0xc2081c1380, 0x17, 0x18, ...)
        /home/aram/go/src/pkg/os/exec_posix.go:45 +0x38b fp=0xc208177138
    os.StartProcess(0xc2081a71d0, 0x27, 0xc2081c1380, 0x17, 0x18, ...)
        /home/aram/go/src/pkg/os/doc.go:24 +0x76 fp=0xc208177188
    os/exec.(*Cmd).Start(0xc208287180, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:272 +0x727 fp=0xc208177328
    os/exec.(*Cmd).Run(0xc208287180, 0x0, 0x0)
        /home/aram/go/src/pkg/os/exec/exec.go:234 +0x4b fp=0xc208177358
    main.(*builder).runOut(0xc208028460, 0xc2080c35e0, 0x1d, 0x68a790, 0x7, ...)
        /home/aram/go/src/cmd/go/build.go:1374 +0x298 fp=0xc208177470
    main.gcToolchain.gc(0xc208028460, 0xc208058800, 0xc2082a1b80, 0x20, 0xc2082cd9e0, ...)
        /home/aram/go/src/cmd/go/build.go:1604 +0xced fp=0xc208177688
    main.gcToolchain.gc·i(0x0, 0xc208028460, 0xc208058800, 0xc2082a1b80, 0x20, ...)
        /home/aram/go/src/cmd/go/bootstrap.go:1 +0x181 fp=0xc208177728
    main.(*builder).build(0xc208028460, 0xc2080a6340, 0x0, 0x0)
        /home/aram/go/src/cmd/go/build.go:907 +0x229a fp=0xc208177ea8
    main.func·005(0xc2080a6340)
        /home/aram/go/src/cmd/go/build.go:682 +0x377 fp=0xc208177f50
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:739 +0x135 fp=0xc208177fa8
    runtime.goexit()
        /home/aram/go/src/pkg/runtime/proc.c:1448 fp=0xc208177fb0
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416
    
    goroutine 16 [semacquire]:
    sync.runtime_Semacquire(0xc2081f7f3c)
        /home/aram/go/src/pkg/runtime/sema.goc:199 +0x30
    sync.(*WaitGroup).Wait(0xc2081d29e0)
        /home/aram/go/src/pkg/sync/waitgroup.go:127 +0x15d
    main.(*builder).do(0xc208028460, 0xc208001450)
        /home/aram/go/src/cmd/go/build.go:748 +0x440
    main.runInstall(0x84e1e0, 0xc20800c090, 0x1, 0x1)
        /home/aram/go/src/cmd/go/build.go:336 +0x31f
    main.main()
        /home/aram/go/src/cmd/go/main.go:161 +0x4fa
    
    goroutine 19 [syscall]:
    os/signal.loop()
        /home/aram/go/src/pkg/os/signal/signal_unix.go:21 +0x1e
    created by os/signal.init·1
        /home/aram/go/src/pkg/os/signal/signal_unix.go:27 +0x32
    
    goroutine 22 [runnable]:
    main.func·006()
        /home/aram/go/src/cmd/go/build.go:726
    created by main.(*builder).do
        /home/aram/go/src/cmd/go/build.go:745 +0x416

@davecheney
Copy link
Contributor

Comment 42:

This issue was closed by revision 28792f5.

Status changed to Fixed.

@dvyukov
Copy link
Member

dvyukov commented Mar 13, 2014

Comment 43:

This issue was updated by revision e678ab4.

LGTM=rsc
R=rsc, aram
CC=golang-codereviews
https://golang.org/cl/75260043

@4ad 4ad added the fixed label Mar 13, 2014
@golang golang locked and limited conversation to collaborators Jun 25, 2016
This issue was closed.
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@davecheney @rsc @dvyukov @4ad @gopherbot