-
Notifications
You must be signed in to change notification settings - Fork 17.9k
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/pprof: TestGoroutineSwitch failure #6417
Comments
tegoor, Please, see if that https://golang.org/cl/13321048/ helps. Thank you. Alex Status changed to Started. |
This issue was closed by revision 521dbbf. Status changed to Fixed. |
This issue was closed by revision 0fc9db7. |
This issue was closed by revision 05ff4d7. |
This is back on with slightly different message: C:\>go version go version devel +8119adb1b8d1 Mon Sep 30 16:02:12 2013 -0700 windows/386 C:\>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- FAIL: TestGoroutineSwitch (1.39 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0] FAIL exit status 1 FAIL runtime/pprof 1.453s C:\> Status changed to Accepted. |
I can make it happen as often as you like, on real hardware or in vm: C:\go\root\src>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- FAIL: TestGoroutineSwitch (0.62 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0 ] FAIL exit status 1 FAIL runtime/pprof 0.688s C:\go\root\src>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- PASS: TestGoroutineSwitch (1.55 seconds) PASS ok runtime/pprof 1.625s C:\go\root\src>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- FAIL: TestGoroutineSwitch (0.47 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0 ] FAIL exit status 1 FAIL runtime/pprof 0.531s C:\go\root\src>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- FAIL: TestGoroutineSwitch (0.16 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0 ] FAIL exit status 1 FAIL runtime/pprof 0.219s C:\go\root\src>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- FAIL: TestGoroutineSwitch (0.16 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0 ] FAIL exit status 1 FAIL runtime/pprof 0.219s C:\go\root\src>go test -v -run=Go runtime/pprof === RUN TestGoroutineSwitch --- FAIL: TestGoroutineSwitch (1.56 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0 ] FAIL exit status 1 FAIL runtime/pprof 1.641s C:\go\root\src> It has been happening on builders too. I am concerned about this too. I am not sure if it has always been that way or if it is recent. Didn't you add these tests recently. As far as I remember windows profile collector runs on dedicated OS thread with a high priority, so it should take over regardless. But we changed some global environment settings recently: https://golang.org/cl/12406043. I don't know if that might affect things. To tell the truth, I didn't investigate it properly yet. I will do that when I have time. Do you have any suggestions of how to proceed? Alex |
"go test -short" works. "go test" fails with C:\go\root\src\pkg\runtime\pprof>go test runtime: out of memory: cannot allocate 1073741824-byte block (1074790400 in use) fatal error: out of memory goroutine 8 [running]: runtime.throw(0x61e7f7) C:/go/root/src/pkg/runtime/panic.c:464 +0x67 fp=0x30dc66c0 runtime.mallocgc(0x40000000, 0x4c4d41, 0x1) C:/go/root/src/pkg/runtime/malloc.goc:91 +0x412 fp=0x30dc66fc cnew(0x4c4d40, 0x40000000, 0x1) C:/go/root/src/pkg/runtime/malloc.goc:718 +0xa9 fp=0x30dc670c runtime.cnewarray(0x4c4d40, 0x40000000) C:/go/root/src/pkg/runtime/malloc.goc:731 +0x3b fp=0x30dc671c makeslice1(0x4c01c0, 0x40000000, 0x40000000, 0x30dc675c) C:/go/root/src/pkg/runtime/slice.c:57 +0x47 fp=0x30dc6728 runtime.makeslice(0x4c01c0, 0x40000000, 0x0, 0x40000000, 0x0, ...) C:/go/root/src/pkg/runtime/slice.c:38 +0x96 fp=0x30dc6748 runtime/pprof_test.TestCPUProfileWithFork(0x10da8420) c:/go/root/src/pkg/runtime/pprof/pprof_test.go:161 +0x78 fp=0x30dc6798 testing.tRunner(0x10da8420, 0x61c5f8) C:/go/root/src/pkg/testing/testing.go:389 +0x87 fp=0x30dc67c4 runtime.goexit() C:/go/root/src/pkg/runtime/proc.c:1396 fp=0x30dc67c8 created by testing.RunTests C:/go/root/src/pkg/testing/testing.go:469 +0x6d2 goroutine 1 [chan receive]: testing.RunTests(0x529508, 0x61c5e0, 0x5, 0x5, 0x1) C:/go/root/src/pkg/testing/testing.go:470 +0x6ed testing.Main(0x529508, 0x61c5e0, 0x5, 0x5, 0x61fe60, ...) C:/go/root/src/pkg/testing/testing.go:401 +0x6a main.main() runtime/pprof/_test/_testmain.go:55 +0x82 exit status 2 FAIL runtime/pprof 1.078s C:\go\root\src\pkg\runtime\pprof> But if I disable TestCPUProfileWithFork, then sometimes "go test" work and sometimes it does not: C:\go\root\src\pkg\runtime\pprof>go test --- FAIL: TestGoroutineSwitch (0.14 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0] FAIL exit status 1 FAIL runtime/pprof 1.391s C:\go\root\src\pkg\runtime\pprof>go test --- FAIL: TestGoroutineSwitch (0.45 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0] FAIL exit status 1 FAIL runtime/pprof 1.703s C:\go\root\src\pkg\runtime\pprof>go test --- FAIL: TestGoroutineSwitch (0.59 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0] FAIL exit status 1 FAIL runtime/pprof 1.844s C:\go\root\src\pkg\runtime\pprof>go test PASS ok runtime/pprof 2.750s C:\go\root\src\pkg\runtime\pprof>go test --- FAIL: TestGoroutineSwitch (0.30 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0] FAIL exit status 1 FAIL runtime/pprof 1.547s C:\go\root\src\pkg\runtime\pprof>go test --- FAIL: TestGoroutineSwitch (0.14 seconds) pprof_test.go:63: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x0 0x1 0x0] FAIL exit status 1 FAIL runtime/pprof 1.406s C:\go\root\src\pkg\runtime\pprof> Alex |
https://code.google.com/p/go/source/browse/src/pkg/runtime/os_windows.c#405 condition is never true. Probably, because TestGoroutineSwitch just calls runtime.Gosched in the loop. Isn't runtime.Gosched is running on g0? Alex |
On non-Windows machines sigprof gets called unconditionally, and it contains code at the top to mark system execution with a fake frame reporting a caller of "System", avoiding the stack walk. This makes sure that even execution on m stacks is mentioned in the profiles, although at less detail than execution on g stacks. It sounds like profilem should try to call sigprof always. |
This https://golang.org/cl/14231047 helps. If we want to pursue it. I am not sure, maybe "gp->status != Gsyscall" should be removed too. Alex |
It works too. Sent https://golang.org/cl/14231047 for review. Alex |
This issue was closed by revision 4207897. Status changed to Fixed. |
OS: windows server 2012 Standard 64bit CPU: E5-2403 RAM: 8G C:\go\src>go version go version devel +168efa7a7a36 Fri Oct 04 13:13:56 2013 +0900 windows/amd64 C:\go\src>go test -short runtime/pprof ok runtime/pprof 3.711s C:\go\src>go test runtime/pprof ok runtime/pprof 7.265s C:\go\src>go test runtime ok runtime 279.242s OS: windows server 2003 Enterprise 32bit CPU: E5405 RAM: 2G D:\golang\src>go version go version devel +168efa7a7a36 Fri Oct 04 13:13:56 2013 +0900 windows/386 D:\golang\src>go test -short runtime/pprof ok runtime/pprof 3.531s D:\golang\src>go test runtime/pprof runtime: out of memory: cannot allocate 1073741824-byte block (1074790400 in use) fatal error: out of memory goroutine 8 [running]: runtime.throw(0x61e7b7) D:/golang/src/pkg/runtime/panic.c:464 +0x67 fp=0x30db56c0 runtime.mallocgc(0x40000000, 0x4c4a41, 0x1) D:/golang/src/pkg/runtime/malloc.goc:91 +0x412 fp=0x30db56fc cnew(0x4c4a40, 0x40000000, 0x1) D:/golang/src/pkg/runtime/malloc.goc:718 +0xa9 fp=0x30db570c runtime.cnewarray(0x4c4a40, 0x40000000) D:/golang/src/pkg/runtime/malloc.goc:731 +0x3b fp=0x30db571c makeslice1(0x4bfec0, 0x40000000, 0x40000000, 0x30db575c) D:/golang/src/pkg/runtime/slice.c:57 +0x47 fp=0x30db5728 runtime.makeslice(0x4bfec0, 0x40000000, 0x0, 0x40000000, 0x0, ...) D:/golang/src/pkg/runtime/slice.c:38 +0x96 fp=0x30db5748 runtime/pprof_test.TestCPUProfileWithFork(0x10da34e0) d:/golang/src/pkg/runtime/pprof/pprof_test.go:161 +0x78 fp=0x30db5798 testing.tRunner(0x10da34e0, 0x61c5b8) D:/golang/src/pkg/testing/testing.go:389 +0x87 fp=0x30db57c4 runtime.goexit() D:/golang/src/pkg/runtime/proc.c:1396 fp=0x30db57c8 created by testing.RunTests D:/golang/src/pkg/testing/testing.go:469 +0x6d2 goroutine 1 [chan receive]: testing.RunTests(0x5291a8, 0x61c5a0, 0x5, 0x5, 0x1) D:/golang/src/pkg/testing/testing.go:470 +0x6ed testing.Main(0x5291a8, 0x61c5a0, 0x5, 0x5, 0x61fe60, ...) D:/golang/src/pkg/testing/testing.go:401 +0x6a main.main() runtime/pprof/_test/_testmain.go:55 +0x82 FAIL runtime/pprof 2.406s D:\golang\src>go test runtime runtime: out of memory: cannot allocate 92274688-byte block (1227358208 in use) fatal error: out of memory goroutine 93 [running]: runtime.throw(0x808037) d:/golang/src/pkg/runtime/panic.c:464 +0x67 fp=0x3109555c runtime.mallocgc(0x5800000, 0x5a8b21, 0x0) D:/golang/src/pkg/runtime/malloc.goc:91 +0x412 fp=0x31095598 cnew(0x5a8b20, 0x200000, 0x1) D:/golang/src/pkg/runtime/malloc.goc:718 +0xa9 fp=0x310955a8 runtime.cnewarray(0x5a8b20, 0x200000) D:/golang/src/pkg/runtime/malloc.goc:731 +0x3b fp=0x310955b8 hash_grow(0x57aae0, 0x110b34e0) d:/golang/src/pkg/runtime/hashmap.c:421 +0x63 fp=0x310955d0 hash_insert(0x57aae0, 0x110b34e0, 0x31095654, 0x31095658) d:/golang/src/pkg/runtime/hashmap.c:620 +0x2b7 fp=0x3109561c runtime.mapassign(0x57aae0, 0x110b34e0, 0x31095654, 0x31095658) d:/golang/src/pkg/runtime/hashmap.c:1085 +0x7b fp=0x31095630 runtime.mapassign1(0x57aae0, 0x110b34e0, 0x58df49b2) d:/golang/src/pkg/runtime/hashmap.c:1114 +0x5e fp=0x3109564c runtime_test.(*HashSet).addB(0x31095750, 0x110aca98, 0x8, 0x8) d:/golang/src/pkg/runtime/hash_test.go:65 +0x7f fp=0x31095668 runtime_test.setbits(0x31095750, 0x110aca98, 0x8, 0x8, 0x40, ...) d:/golang/src/pkg/runtime/hash_test.go:221 +0x42 fp=0x31095688 runtime_test.setbits(0x31095750, 0x110aca98, 0x8, 0x8, 0x38, ...) d:/golang/src/pkg/runtime/hash_test.go:227 +0xd1 fp=0x310956a8 runtime_test.setbits(0x31095750, 0x110aca98, 0x8, 0x8, 0x22, ...) d:/golang/src/pkg/runtime/hash_test.go:227 +0xd1 fp=0x310956c8 runtime_test.setbits(0x31095750, 0x110aca98, 0x8, 0x8, 0x19, ...) d:/golang/src/pkg/runtime/hash_test.go:227 +0xd1 fp=0x310956e8 runtime_test.setbits(0x31095750, 0x110aca98, 0x8, 0x8, 0x13, ...) d:/golang/src/pkg/runtime/hash_test.go:227 +0xd1 fp=0x31095708 runtime_test.setbits(0x31095750, 0x110aca98, 0x8, 0x8, 0x0, ...) d:/golang/src/pkg/runtime/hash_test.go:227 +0xd1 fp=0x31095728 runtime_test.sparse(0x11082660, 0x40, 0x5) d:/golang/src/pkg/runtime/hash_test.go:215 +0xda fp=0x31095768 runtime_test.TestSmhasherSparse(0x11082660) d:/golang/src/pkg/runtime/hash_test.go:207 +0x145 fp=0x31095798 testing.tRunner(0x11082660, 0x8084c4) D:/golang/src/pkg/testing/testing.go:389 +0x87 fp=0x310957c4 runtime.goexit() d:/golang/src/pkg/runtime/proc.c:1396 fp=0x310957c8 created by testing.RunTests D:/golang/src/pkg/testing/testing.go:469 +0x6d2 goroutine 1 [chan receive]: testing.RunTests(0x61d070, 0x808380, 0x56, 0x56, 0x1) D:/golang/src/pkg/testing/testing.go:470 +0x6ed testing.Main(0x61d070, 0x808380, 0x56, 0x56, 0x809140, ...) D:/golang/src/pkg/testing/testing.go:401 +0x6a main.main() runtime/_test/_testmain.go:521 +0x82 FAIL runtime 250.078s |
This is still broken. For example, see http://build.golang.org/ windows-386 build logs for 7bc58b0d9de0 and ad51691011d3. Alex Status changed to Accepted. |
I collected all snapshots of what is happening on the system for the failed TestGoroutineSwitch round, everything that current profile collector discards: runtime.atomicloadp /root/go/root/src/pkg/runtime/atomic_386.c:19 runtime.atomicloadp /root/go/root/src/pkg/runtime/atomic_386.c:19 runtime.unlock /root/go/root/src/pkg/runtime/lock_sema.c:101 runtime.casp /root/go/root/src/pkg/runtime/asm_386.s:457 runtime.casp /root/go/root/src/pkg/runtime/asm_386.s:461 execute /root/go/root/src/pkg/runtime/proc.c:1125 globrunqget /root/go/root/src/pkg/runtime/proc.c:2664 schedule /root/go/root/src/pkg/runtime/proc.c:1309 findrunnable /root/go/root/src/pkg/runtime/proc.c:1152 schedule /root/go/root/src/pkg/runtime/proc.c:1288 runtime.mcall /root/go/root/src/pkg/runtime/asm_386.s:189 runtime.casp /root/go/root/src/pkg/runtime/asm_386.s:461 runtime.unlock /root/go/root/src/pkg/runtime/lock_sema.c:117 runtime.unlock /root/go/root/src/pkg/runtime/lock_sema.c:115 findrunnable /root/go/root/src/pkg/runtime/proc.c:1134 All of these look like scheduler or some such. So it is no surprise this test fails. Alex |
Is this what is causing this build failure on windows-amd64? --- FAIL: TestCPUProfileMultithreaded (1.87 seconds) pprof_test.go:129: crc32.ChecksumIEEE: 22 pprof_test.go:129: crc32.Update: 2 pprof_test.go:139: crc32.Update has 2 samples out of 24, want at least 4, ideally 12 FAIL FAIL runtime/pprof 3.580s |
This issue was updated by revision 9a420b7. R=golang-dev, rsc CC=golang-dev https://golang.org/cl/14604043 |
This issue was closed by revision 9aee98d. Status changed to Fixed. |
This issue was closed by revision 8a3c587. Status changed to Fixed. |
by tegoor:
The text was updated successfully, but these errors were encountered: