Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

runtime: TestCgoCCodeSIGPROF hangs #14766

Closed
alexbrainman opened this issue Mar 11, 2016 · 6 comments
Closed

runtime: TestCgoCCodeSIGPROF hangs #14766

alexbrainman opened this issue Mar 11, 2016 · 6 comments
Milestone

Comments

@alexbrainman
Copy link
Member

go version devel +31d13f4 Fri Mar 11 00:56:04 2016 +0000 linux/386

Running

go test -run=TestCgoCCodeSIGPROF runtime

hangs forever.

Pressing ctrl+\ prints:

SIGQUIT: quit
PC=0x809c88d m=0

goroutine 0 [idle]:
runtime.futex(0x831d4e4, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1, 0x0, 0x0, 0x831d190, ...)
    /root/go/src/runtime/sys_linux_386.s:289 +0x1d fp=0xbfcca62c sp=0xbfcca628
runtime.futexsleep(0x831d4e4, 0x0, 0xffffffff, 0xffffffff)
    /root/go/src/runtime/os1_linux.go:40 +0x55 fp=0xbfcca658 sp=0xbfcca62c
runtime.notesleep(0x831d4e4)
    /root/go/src/runtime/lock_futex.go:145 +0x9e fp=0xbfcca670 sp=0xbfcca658
runtime.stoplockedm()
    /root/go/src/runtime/proc.go:1664 +0x9e fp=0xbfcca680 sp=0xbfcca670
runtime.schedule()
    /root/go/src/runtime/proc.go:2012 +0x66 fp=0xbfcca6a0 sp=0xbfcca680
runtime.park_m(0x185000d0)
    /root/go/src/runtime/proc.go:2117 +0x154 fp=0xbfcca6b4 sp=0xbfcca6a0
runtime.mcall(0xbfcca6c8)
    /root/go/src/runtime/asm_386.s:255 +0x47 fp=0xbfcca6bc sp=0xbfcca6b4

goroutine 1 [chan receive, locked to thread]:
runtime.gopark(0x826dd0c, 0x1854a3f0, 0x8231b0a, 0xc, 0xb753a017, 0x3)
    /root/go/src/runtime/proc.go:262 +0x130 fp=0x18547d70 sp=0x18547d5c
runtime.goparkunlock(0x1854a3f0, 0x8231b0a, 0xc, 0x831d417, 0x3)
    /root/go/src/runtime/proc.go:268 +0x4b fp=0x18547d8c sp=0x18547d70
runtime.chanrecv(0x81d1560, 0x1854a3c0, 0x18547e80, 0x18547d01, 0x80a0000)
    /root/go/src/runtime/chan.go:474 +0x3d4 fp=0x18547dd4 sp=0x18547d8c
runtime.chanrecv1(0x81d1560, 0x1854a3c0, 0x18547e80)
    /root/go/src/runtime/chan.go:357 +0x24 fp=0x18547dec sp=0x18547dd4
testing.RunTests(0x826da08, 0x831b280, 0xb4, 0xb4, 0x80f5501)
    /root/go/src/testing/testing.go:582 +0x724 fp=0x18547eac sp=0x18547dec
testing.(*M).Run(0x18547f7c, 0x82c07dc)
    /root/go/src/testing/testing.go:515 +0x79 fp=0x18547ef0 sp=0x18547eac
runtime_test.TestMain(0x18547f7c)
    /root/go/src/runtime/crash_test.go:24 +0x25 fp=0x18547f30 sp=0x18547ef0
main.main()
    runtime/_test/_testmain.go:960 +0x100 fp=0x18547fa8 sp=0x18547f30
runtime.main()
    /root/go/src/runtime/proc.go:188 +0x276 fp=0x18547fd0 sp=0x18547fa8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x18547fd4 sp=0x18547fd0

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x18536fdc sp=0x18536fd8

goroutine 2 [force gc (idle)]:
runtime.gopark(0x826dd0c, 0x831cc90, 0x8234422, 0xf, 0x13bdf14, 0x1)
    /root/go/src/runtime/proc.go:262 +0x130 fp=0x185227ac sp=0x18522798
runtime.goparkunlock(0x831cc90, 0x8234422, 0xf, 0x18500014, 0x1)
    /root/go/src/runtime/proc.go:268 +0x4b fp=0x185227c8 sp=0x185227ac
runtime.forcegchelper()
    /root/go/src/runtime/proc.go:229 +0xaa fp=0x185227e0 sp=0x185227c8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x185227e4 sp=0x185227e0
created by runtime.init.4
    /root/go/src/runtime/proc.go:218 +0x2a

goroutine 3 [GC sweep wait]:
runtime.gopark(0x826dd0c, 0x831cde0, 0x82325a6, 0xd, 0x8064814, 0x1)
    /root/go/src/runtime/proc.go:262 +0x130 fp=0x18522fa0 sp=0x18522f8c
runtime.goparkunlock(0x831cde0, 0x82325a6, 0xd, 0x14, 0x1)
    /root/go/src/runtime/proc.go:268 +0x4b fp=0x18522fbc sp=0x18522fa0
runtime.bgsweep(0x1854a000)
    /root/go/src/runtime/mgcsweep.go:63 +0xa0 fp=0x18522fd8 sp=0x18522fbc
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x18522fdc sp=0x18522fd8
created by runtime.gcenable
    /root/go/src/runtime/mgc.go:191 +0x52

goroutine 4 [finalizer wait]:
runtime.gopark(0x826dd0c, 0x832d6cc, 0x8233616, 0xe, 0x14, 0x1)
    /root/go/src/runtime/proc.go:262 +0x130 fp=0x1852378c sp=0x18523778
runtime.goparkunlock(0x832d6cc, 0x8233616, 0xe, 0x14, 0x1)
    /root/go/src/runtime/proc.go:268 +0x4b fp=0x185237a8 sp=0x1852378c
runtime.runfinq()
    /root/go/src/runtime/mfinal.go:158 +0x9e fp=0x185237e0 sp=0x185237a8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x185237e4 sp=0x185237e0
created by runtime.createfing
    /root/go/src/runtime/mfinal.go:139 +0x5c

goroutine 5 [syscall]:
syscall.Syscall6(0x72, 0xfc4, 0x18537d98, 0x0, 0x1856a2d0, 0x0, 0x0, 0x18537d88, 0x8095d60, 0x18537d84)
    /root/go/src/syscall/asm_linux_386.s:45 +0x5 fp=0x18537d48 sp=0x18537d44
syscall.wait4(0xfc4, 0x18537d98, 0x0, 0x1856a2d0, 0x50, 0x0, 0x0)
    /root/go/src/syscall/zsyscall_linux_386.go:172 +0x71 fp=0x18537d7c sp=0x18537d48
syscall.Wait4(0xfc4, 0x18537dbc, 0x0, 0x1856a2d0, 0x185263c0, 0x0, 0x0)
    /root/go/src/syscall/syscall_linux.go:256 +0x4d fp=0x18537da0 sp=0x18537d7c
os.(*Process).wait(0x1850ab10, 0x1e, 0x0, 0x0)
    /root/go/src/os/exec_unix.go:22 +0xbe fp=0x18537df8 sp=0x18537da0
os.(*Process).Wait(0x1850ab10, 0x0, 0x0, 0x0)
    /root/go/src/os/doc.go:49 +0x2b fp=0x18537e0c sp=0x18537df8
os/exec.(*Cmd).Wait(0x1850e5a0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:396 +0x186 fp=0x18537e74 sp=0x18537e0c
os/exec.(*Cmd).Run(0x1850e5a0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:262 +0x58 fp=0x18537e8c sp=0x18537e74
os/exec.(*Cmd).CombinedOutput(0x1850e5a0, 0x0, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/os/exec/exec.go:453 +0x23f fp=0x18537edc sp=0x18537e8c
runtime_test.runTestProg(0x185721e0, 0x8231136, 0xb, 0x82340da, 0xf, 0x0, 0x0)
    /root/go/src/runtime/crash_test.go:68 +0x194 fp=0x18537f48 sp=0x18537edc
runtime_test.TestCgoCCodeSIGPROF(0x185721e0)
    /root/go/src/runtime/crash_cgo_test.go:206 +0x47 fp=0x18537fac sp=0x18537f48
testing.tRunner(0x185721e0, 0x831b3dc)
    /root/go/src/testing/testing.go:473 +0x8f fp=0x18537fd0 sp=0x18537fac
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x18537fd4 sp=0x18537fd0
created by testing.RunTests
    /root/go/src/testing/testing.go:581 +0x6f2

goroutine 8 [syscall]:
syscall.Syscall(0x3, 0x4, 0x18592400, 0x200, 0x18592400, 0x200, 0x0)
    /root/go/src/syscall/asm_linux_386.s:20 +0x5 fp=0x18523e04 sp=0x18523e00
syscall.read(0x4, 0x18592400, 0x200, 0x200, 0x826d9dc, 0x0, 0x0)
    /root/go/src/syscall/zsyscall_linux_386.go:783 +0x4f fp=0x18523e24 sp=0x18523e04
syscall.Read(0x4, 0x18592400, 0x200, 0x200, 0x0, 0x0, 0x0)
    /root/go/src/syscall/syscall_unix.go:161 +0x45 fp=0x18523e44 sp=0x18523e24
os.(*File).read(0x185263b8, 0x18592400, 0x200, 0x200, 0x18592400, 0x0, 0x0)
    /root/go/src/os/file_unix.go:228 +0x4a fp=0x18523e64 sp=0x18523e44
os.(*File).Read(0x185263b8, 0x18592400, 0x200, 0x200, 0x344, 0x0, 0x0)
    /root/go/src/os/file.go:95 +0x6f fp=0x18523e90 sp=0x18523e64
bytes.(*Buffer).ReadFrom(0x18572300, 0xb6ced310, 0x185263b8, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/bytes/buffer.go:176 +0x1c5 fp=0x18523ee8 sp=0x18523e90
io.copyBuffer(0xb6ced440, 0x18572300, 0xb6ced310, 0x185263b8, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /root/go/src/io/io.go:374 +0x129 fp=0x18523f4c sp=0x18523ee8
io.Copy(0xb6ced440, 0x18572300, 0xb6ced310, 0x185263b8, 0x0, 0x0, 0x0, 0x0)
    /root/go/src/io/io.go:350 +0x53 fp=0x18523f7c sp=0x18523f4c
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
    /root/go/src/os/exec/exec.go:236 +0x72 fp=0x18523fc0 sp=0x18523f7c
os/exec.(*Cmd).Start.func1(0x1850e5a0, 0x1850a9e0)
    /root/go/src/os/exec/exec.go:344 +0x1d fp=0x18523fd8 sp=0x18523fc0
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x18523fdc sp=0x18523fd8
created by os/exec.(*Cmd).Start
    /root/go/src/os/exec/exec.go:345 +0x787

eax    0xf0
ebx    0x831d4e4
ecx    0x0
edx    0x0
edi    0x0
esi    0x0
ebp    0x0
esp    0xbfcca628
eip    0x809c88d
eflags 0x286
cs     0x73
fs     0x0
gs     0x33
FAIL    runtime 15.667s

Alex

@ianlancetaylor
Copy link
Contributor

Unfortunately that stack trace is not too useful, as it is from the calling program rather than the actual test program. Please try

go build runtime/testdata/testprogcgo
./testprogcgo CgoCCodeSIGPROF

I assume it will hang. Try ^\ to see what the stack trace is. Thanks.

@ianlancetaylor ianlancetaylor added this to the Go1.7 milestone Mar 11, 2016
@ianlancetaylor ianlancetaylor self-assigned this Mar 11, 2016
@alexbrainman
Copy link
Member Author

It outputs this:

SIGQUIT: quit
PC=0x8097e3d m=0

goroutine 7 [syscall]:
runtime.notetsleepg(0xb5ba9004, 0xffffffff, 0xffffffff, 0x0)
    /root/go/src/runtime/lock_futex.go:205 +0x4d fp=0x18324f0c sp=0x18324ef4
runtime.(*cpuProfile).getprofile(0xb5ba9000, 0x0, 0x0, 0x0)
    /root/go/src/runtime/cpuprof.go:341 +0x4ff fp=0x18324f94 sp=0x18324f0c
runtime.CPUProfile(0x0, 0x0, 0x0)
    /root/go/src/runtime/cpuprof.go:421 +0x31 fp=0x18324fa8 sp=0x18324f94
runtime/pprof.profileWriter(0xb65370f8, 0x18360000)
    /root/go/src/runtime/pprof/pprof.go:617 +0x1a fp=0x18324fd8 sp=0x18324fa8
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1 fp=0x18324fdc sp=0x18324fd8
created by runtime/pprof.StartCPUProfile
    /root/go/src/runtime/pprof/pprof.go:611 +0x123

goroutine 1 [chan receive]:
main.CgoCCodeSIGPROF()
    /root/go/src/runtime/testdata/testprogcgo/aprof.go:44 +0xcf
main.main()
    /root/go/src/runtime/testdata/testprogcgo/main.go:34 +0x17b

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1

goroutine 5 [syscall]:
os/signal.signal_recv(0x0)
    /root/go/src/runtime/sigqueue.go:116 +0x11e
os/signal.loop()
    /root/go/src/os/signal/signal_unix.go:22 +0x1a
created by os/signal.init.1
    /root/go/src/os/signal/signal_unix.go:28 +0x36

goroutine 6 [runnable]:
main._Cfunc_GoNop()
    runtime/testdata/testprogcgo/_obj/_cgo_gotypes.go:67
main.CgoCCodeSIGPROF.func1(0x1834a080)
    /root/go/src/runtime/testdata/testprogcgo/aprof.go:35 +0x43
created by main.CgoCCodeSIGPROF
    /root/go/src/runtime/testdata/testprogcgo/aprof.go:39 +0x56

goroutine 18 [syscall, locked to thread]:
runtime.goexit()
    /root/go/src/runtime/asm_386.s:1591 +0x1

eax    0xf0
ebx    0xb5ba9004
ecx    0x0
edx    0x0
edi    0x0
esi    0x0
ebp    0x0
esp    0x18324ea4
eip    0x8097e3d
eflags 0x286
cs     0x73
fs     0x0
gs     0x33

Alex

@ianlancetaylor
Copy link
Contributor

Odd. No idea what is happening. The stack trace looks ordinary. It works for me with GOARCH=386.

How slow is your processor, and how long are you letting the program run? The program takes 5 seconds on my laptop. Can you edit runtime/testdata/testprogcgo/aprof.go and change the loop calling GoNop from 1e7 to 1e4 or something, and see whether the program completes?

@alexbrainman
Copy link
Member Author

It works if I change the test:

# git diff
diff --git a/src/runtime/testdata/testprogcgo/aprof.go b/src/runtime/testdata/testprogcgo/aprof.go
index cf52107..a6c93a0 100644
--- a/src/runtime/testdata/testprogcgo/aprof.go
+++ b/src/runtime/testdata/testprogcgo/aprof.go
@@ -31,7 +31,7 @@ func CgoCCodeSIGPROF() {
        go func() {
                for {
                        <-c
-                       for i := 0; i < 1e7; i++ {
+                       for i := 0; i < 1e4; i++ {
                                C.GoNop()
                        }
                        c <- true
# go test -run=TestCgoCCodeSIGPROF runtime
ok      runtime 1.662s
# cat /proc/cpuinfo | grep 'model name'
model name      : Intel(R) Xeon(R) CPU           E5530  @ 2.40GHz
#

I noticed the problem because my all.bash could not complete, because runtime test would time out.

Alex

@ianlancetaylor
Copy link
Contributor

Does https://golang.org/cl/20590 fix this for you?

@alexbrainman
Copy link
Member Author

Yes CL 20590 fixes it for me:

# go test -run=TestCgoCCodeSIGPROF runtime
ok      runtime 4.425s
# go test runtime -short
ok      runtime 39.594s
#

Thank you.

Alex

@golang golang locked and limited conversation to collaborators Mar 13, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants