Comment 1:

tegoor,
Please, see if that https://golang.org/cl/13321048/ helps. Thank you.
Alex

Status changed to Started.

Comment 2:

This issue was closed by revision 521dbbf.

Status changed to Fixed.

Comment 3:

This issue was closed by revision 0fc9db7.

Comment 4:

This issue was closed by revision 05ff4d7.

Comment 5:

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.

Comment 6:

How often can you make this happen? That's no samples for a 1.4 second run, which is not
good. That is, it's a real failure.

Comment 7:

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

Comment 8:

I'd start by running all the tests. If the other tests are passing and it's
just the TestGoroutineSwitch, then that limits how much we need to look at.

Comment 9:

(that is, all the tests in runtime/pprof)

Comment 10:

"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

Comment 11:

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

Comment 12:

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.

Comment 13:

Should we start making changes now? If not, what do we do about these failing tests?
Alex

Comment 14:

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

Comment 15:

I think it's fine to make changes to this. I would try 'if(gp != nil)' and
see how it goes from there.

Comment 16:

It works too. Sent https://golang.org/cl/14231047 for review.
Alex

Comment 17:

This issue was closed by revision 4207897.

Status changed to Fixed.

Comment 18 by tegoor:

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

Comment 19:

tegoor,
Please, open new issue for these. They aren't related to the current issue. Thank you.
Alex

Comment 20:

This is still broken. For example, see http://build.golang.org/ windows-386 build logs
for 7bc58b0d9de0 and ad51691011d3.
Alex

Status changed to Accepted.

Comment 21:

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

Comment 22:

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

Comment 23:

This issue was updated by revision 9a420b7.

R=golang-dev, rsc
CC=golang-dev
https://golang.org/cl/14604043

Comment 24:

This issue was closed by revision 9aee98d.

Status changed to Fixed.

Comment 25:

This is still on. We are just skipping TestGoroutineSwitch test for the moment. Until we
have a solution.
Alex

Status changed to Accepted.

Comment 26:

Labels changed: added go1.3maybe.

Comment 27:

Labels changed: added release-none, removed go1.3maybe.

Comment 28:

Labels changed: added repo-main.

Comment 29:

This issue was closed by revision 8a3c587.

Status changed to Fixed.