runtime/pprof: TestGoroutineSwitch failure

[gopherbot]

by tegoor:

What steps will reproduce the problem?
go test runtime/pprof -short

What do you see instead?
--- FAIL: TestGoroutineSwitch (0.23 seconds)
        pprof_test.go:62: profile too short: [0x0 0x3 0x0 0x2710 0x0 0x1 0x2 0x4
213de 0x4173d1 0x0 0x1 0x0]
FAIL
FAIL    runtime/pprof   3.547s

Which compiler are you using (5g, 6g, 8g, gccgo)?
8g

Which operating system are you using?
windows 2003 Standard Edition SP2

Which version are you using?  (run 'go version')
go version devel +84975e4930dd Tue Sep 17 18:06:58 2013 -0700 windows/386

[alexbrainman]

Comment 1:

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

Status changed to Started.

[alexbrainman]

Comment 2:

This issue was closed by revision 521dbbf.

Status changed to Fixed.

[rsc]

Comment 3:

This issue was closed by revision 0fc9db7.

[rsc]

Comment 4:

This issue was closed by revision 05ff4d7.

[alexbrainman]

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.

[rsc]

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.

[alexbrainman]

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

[rsc]

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.

[rsc]

Comment 9:

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

[alexbrainman]

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

[alexbrainman]

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

[rsc]

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.

[alexbrainman]

Comment 13:

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

[alexbrainman]

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

[rsc]

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.