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

internal/trace/v2: test timeouts #64794

Open
gopherbot opened this issue Dec 19, 2023 · 16 comments
Open

internal/trace/v2: test timeouts #64794

gopherbot opened this issue Dec 19, 2023 · 16 comments
Assignees
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@gopherbot
Copy link

gopherbot commented Dec 19, 2023

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`

Issue created automatically to collect these failures.

Example (log):

--- FAIL: TestTraceManyStartStop (0.74s)
    --- FAIL: TestTraceManyStartStop/Default (0.74s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/many-start-stop.go
        trace_test.go:551: stderr: SIGQUIT: quit
            PC=0x250a4627 m=3 sigcode=0

            goroutine 0 gp=0x57406b48 m=3 mp=0x57440b08 [idle]:
            runtime.kevent(0x36, 0x0, 0x0, 0x19f70acc, 0x40, 0x19f70aa4)
            	runtime/sys_openbsd2.go:219 +0x21 fp=0x19f70a68 sp=0x19f70a58 pc=0x80a5541
            runtime.netpoll(0x3478c32f)
...
            edi    0x784
            esi    0x57406b48
            ebp    0x19f70a18
            esp    0x19f709fc
            eip    0x250a4627
            eflags 0x207
            cs     0x2b
            fs     0x5b
            gs     0x63
        trace_test.go:553: exit status 2

watchflakes

@gopherbot gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 19, 2023
@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
default <- pkg == "internal/trace/v2" && test == "TestTraceManyStartStop"
2023-12-18 21:30 openbsd-386-72 go@c564d4ae internal/trace/v2.TestTraceManyStartStop (log)
--- FAIL: TestTraceManyStartStop (0.74s)
    --- FAIL: TestTraceManyStartStop/Default (0.74s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/many-start-stop.go
        trace_test.go:551: stderr: SIGQUIT: quit
            PC=0x250a4627 m=3 sigcode=0

            goroutine 0 gp=0x57406b48 m=3 mp=0x57440b08 [idle]:
            runtime.kevent(0x36, 0x0, 0x0, 0x19f70acc, 0x40, 0x19f70aa4)
            	runtime/sys_openbsd2.go:219 +0x21 fp=0x19f70a68 sp=0x19f70a58 pc=0x80a5541
            runtime.netpoll(0x3478c32f)
...
            edi    0x784
            esi    0x57406b48
            ebp    0x19f70a18
            esp    0x19f709fc
            eip    0x250a4627
            eflags 0x207
            cs     0x2b
            fs     0x5b
            gs     0x63
        trace_test.go:553: exit status 2

watchflakes

@bcmills bcmills added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jan 2, 2024
@bcmills bcmills changed the title internal/trace/v2: TestTraceManyStartStop failures internal/trace/v2: test timeouts Jan 2, 2024
@bcmills
Copy link
Contributor

bcmills commented Jan 2, 2024

Given that TestTraceManyStartStop was running for less than a second before it timed out, it seems likely that some other test in this package is too long/expensive and should be skipped when testing.Short() is true.

(attn @mknyszek)

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-01-08 18:52 gotip-linux-amd64-longtest go@8eaa7935 internal/trace/v2.TestTraceStacks/Stress (log)
=== RUN   TestTraceStacks/Stress
    exec.go:193: test timed out while running command: /home/swarming/.swarming/w/ir/x/w/goroot/bin/go run testdata/testprog/stacks.go
    trace_test.go:553: signal: killed
--- FAIL: TestTraceStacks/Stress (842.69s)

watchflakes

@bcmills
Copy link
Contributor

bcmills commented Jan 24, 2024

https://storage.googleapis.com/go-build-log/33992f4a/openbsd-amd64-72_ed2d35db.log shows a timeout with a long running time in TestTraceStressStartStop/Default.

That one is a bit strange because it seems to show a go run command with a lot of goroutines in buildActionID, waiting on the results of go tool compile -V=full. 🤔

@mknyszek
Copy link
Contributor

These tests do invoke the compiler, but only on very small programs. Still, if that's a problem, I can restructure the tests to group all the programs together like src/runtime/testdata/testprog. (Originally there weren't enough of them for me to consider that necessary, but maybe now there's enough that it causes problems...)

@bcmills
Copy link
Contributor

bcmills commented Jan 24, 2024

It seems odd to me that the go run command stalled for that long on the builder in the first place. I'm not sure what's going on there. Linking can be expensive, but that go run command doesn't seem to have even gotten that far. I wonder if that's another symptom of a bug in the kqueue netpoll implementation...

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-01-29 19:39 openbsd-386-72 go@b91bad78 internal/trace/v2.TestTraceStressStartStop (log)
--- FAIL: TestTraceStressStartStop (158.22s)
    --- FAIL: TestTraceStressStartStop/Default (158.22s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress-start-stop.go
        trace_test.go:562: exit status 1

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-02-22 01:57 gotip-linux-amd64-longtest-race go@5d4e8f51 internal/trace/v2.TestTraceStacks/Stress (log)
=== RUN   TestTraceStacks/Stress
    exec.go:193: test timed out while running command: /home/swarming/.swarming/w/ir/x/w/goroot/bin/go run -race testdata/testprog/stacks.go
    trace_test.go:567: signal: killed
--- FAIL: TestTraceStacks/Stress (1676.23s)

watchflakes

@mknyszek
Copy link
Contributor

Woooaaah... that is way longer than that test should ever take. That could be a deadlock, perhaps. I'll try to reproduce.

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-03-05 20:52 linux-mipsle-rtrk go@9e3b1d53 internal/trace/v2.TestTraceStressStartStop (log)
--- FAIL: TestTraceStressStartStop (658.46s)
    --- FAIL: TestTraceStressStartStop/Default (658.46s)
        exec.go:193: test timed out while running command: /tmp/gobuilder-mips64le/go/bin/go run testdata/testprog/stress-start-stop.go
        trace_test.go:567: signal: killed

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-03-22 04:41 gotip-linux-amd64-longtest-race go@ac0b2f95 internal/trace/v2.TestTraceStacks/Stress (log)
=== RUN   TestTraceStacks/Stress
    exec.go:193: test timed out while running command: /home/swarming/.swarming/w/ir/x/w/goroot/bin/go run -race testdata/testprog/stacks.go
    trace_test.go:567: signal: killed
--- FAIL: TestTraceStacks/Stress (1665.72s)

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-03-27 17:55 openbsd-386-72 go@979b34b3 internal/trace/v2.TestTraceStressStartStop (log)
--- FAIL: TestTraceStressStartStop (54.60s)
    --- FAIL: TestTraceStressStartStop/Default (54.60s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress-start-stop.go
        trace_test.go:571: signal: killed
panic: test timed out after 3m0s
running tests:
	TestTraceIterPull (1s)

goroutine 126 gp=0x6b0070e8 m=0 mp=0x83aa020 [running]:
panic({0x8212be0, 0x6be62878})
...
runtime.chansend1(0x6b3a78c0, 0x6b087fd4)
	/tmp/workdir/go/src/runtime/chan.go:146 +0x24 fp=0x6b087f38 sp=0x6b087f20 pc=0x804d224
os/exec.(*Cmd).watchCtx(0x6b3b1388, 0x6b3a78c0)
	/tmp/workdir/go/src/os/exec/exec.go:848 +0x4c6 fp=0x6b087fe4 sp=0x6b087f38 pc=0x8161006
os/exec.(*Cmd).Start.gowrap2()
	/tmp/workdir/go/src/os/exec/exec.go:750 +0x28 fp=0x6b087ff0 sp=0x6b087fe4 pc=0x81608f8
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1393 +0x1 fp=0x6b087ff4 sp=0x6b087ff0 pc=0x80baa11
created by os/exec.(*Cmd).Start in goroutine 121
	/tmp/workdir/go/src/os/exec/exec.go:750 +0x901

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-04-05 22:18 openbsd-386-72 go@58c5db31 internal/trace/v2.TestTraceStressStartStop (log)
--- FAIL: TestTraceStressStartStop (72.49s)
    --- FAIL: TestTraceStressStartStop/Default (72.49s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress-start-stop.go
        trace_test.go:575: signal: killed
2024-04-05 22:18 openbsd-386-72 go@58c5db31 internal/trace/v2.TestTraceWaitOnPipe (log)
--- FAIL: TestTraceWaitOnPipe (1.73s)
    --- FAIL: TestTraceWaitOnPipe/Default (1.73s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/wait-on-pipe.go
        trace_test.go:573: stderr: SIGQUIT: quit
            PC=0x2e651b1b m=3 sigcode=0

            goroutine 0 gp=0x50c08b48 m=3 mp=0x50c40a08 [idle]:
            runtime.thrsleep
        trace_test.go:575: signal: killed
2024-04-05 22:18 openbsd-386-72 go@58c5db31 internal/trace/v2.TestTraceIterPull (log)
--- FAIL: TestTraceIterPull (0.00s)
    --- FAIL: TestTraceIterPull/Default (0.00s)
        trace_test.go:575: context deadline exceeded
panic: test timed out after 3m0s

goroutine 124 gp=0x61c06d88 m=2 mp=0x61c3a508 [running]:
panic({0x8213ca0, 0x638b8808})
	/tmp/workdir/go/src/runtime/panic.go:778 +0x138 fp=0x61c36784 sp=0x61c36730 pc=0x8081cb8
testing.(*M).startAlarm.func1()
	/tmp/workdir/go/src/testing/testing.go:2366 +0x386 fp=0x61c367f0 sp=0x61c36784 pc=0x813d2f6
...
runtime.gopark(0x82560ec, 0x61c180f0, 0x1a, 0xa, 0x0)
	/tmp/workdir/go/src/runtime/proc.go:402 +0xfa fp=0x61c38f8c sp=0x61c38f78 pc=0x808569a
runtime.gcBgMarkWorker(0x61c1ea00)
	/tmp/workdir/go/src/runtime/mgc.go:1333 +0xeb fp=0x61c38fe8 sp=0x61c38f8c pc=0x80636db
runtime.gcBgMarkStartWorkers.gowrap1()
	/tmp/workdir/go/src/runtime/mgc.go:1249 +0x21 fp=0x61c38ff0 sp=0x61c38fe8 pc=0x80635d1
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1393 +0x1 fp=0x61c38ff4 sp=0x61c38ff0 pc=0x80bb191
created by runtime.gcBgMarkStartWorkers in goroutine 10
	/tmp/workdir/go/src/runtime/mgc.go:1249 +0x114

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-04-09 20:03 openbsd-386-72 go@a555ac63 internal/trace/v2.TestTraceStressStartStop (log)
--- FAIL: TestTraceStressStartStop (123.61s)
    --- FAIL: TestTraceStressStartStop/Default (123.61s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress-start-stop.go
        trace_test.go:575: exit status 1

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-04-15 19:10 openbsd-386-72 go@cfbe6cd9 internal/trace/v2.TestTraceStress (log)
--- FAIL: TestTraceStress (132.95s)
    --- FAIL: TestTraceStress/Default (132.95s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress.go
        trace_test.go:575: signal: killed
panic: test timed out after 3m0s
running tests:
	TestTraceStressStartStop (7s)
	TestTraceStressStartStop/Default (7s)

goroutine 108 gp=0x5e407c28 m=2 mp=0x5e43a508 [running]:
...
runtime.chansend1(0x5e7a6200, 0x5e483fd4)
	/tmp/workdir/go/src/runtime/chan.go:146 +0x24 fp=0x5e483f38 sp=0x5e483f20 pc=0x804d224
os/exec.(*Cmd).watchCtx(0x5e7c8008, 0x5e7a6200)
	/tmp/workdir/go/src/os/exec/exec.go:848 +0x4c6 fp=0x5e483fe4 sp=0x5e483f38 pc=0x8161f26
os/exec.(*Cmd).Start.gowrap2()
	/tmp/workdir/go/src/os/exec/exec.go:750 +0x28 fp=0x5e483ff0 sp=0x5e483fe4 pc=0x8161818
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1393 +0x1 fp=0x5e483ff4 sp=0x5e483ff0 pc=0x80bb4f1
created by os/exec.(*Cmd).Start in goroutine 103
	/tmp/workdir/go/src/os/exec/exec.go:750 +0x901

watchflakes

@gopherbot
Copy link
Author

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && `test timed out`
2024-04-16 21:06 openbsd-386-72 go@15cec430 internal/trace/v2.TestTraceStress (log)
--- FAIL: TestTraceStress (133.33s)
    --- FAIL: TestTraceStress/Default (133.33s)
        exec.go:193: test timed out while running command: /tmp/workdir/go/bin/go run testdata/testprog/stress.go
        trace_test.go:575: signal: killed
panic: test timed out after 3m0s
running tests:
	TestTraceStressStartStop (7s)
	TestTraceStressStartStop/Default (7s)

goroutine 108 gp=0x62c070e8 m=2 mp=0x62c3a508 [running]:
...
internal/trace/v2_test.testTraceProg.func2(0x6300c208)
	/tmp/workdir/go/src/internal/trace/v2/trace_test.go:611 +0x22 fp=0x62c85f98 sp=0x62c85f8c pc=0x81f8562
testing.tRunner(0x6300c208, 0x63a520e8)
	/tmp/workdir/go/src/testing/testing.go:1689 +0x11f fp=0x62c85fe4 sp=0x62c85f98 pc=0x813927f
testing.(*T).Run.gowrap1()
	/tmp/workdir/go/src/testing/testing.go:1742 +0x28 fp=0x62c85ff0 sp=0x62c85fe4 pc=0x813a258
runtime.goexit({})
	/tmp/workdir/go/src/runtime/asm_386.s:1393 +0x1 fp=0x62c85ff4 sp=0x62c85ff0 pc=0x80bb4f1
created by testing.(*T).Run in goroutine 102
	/tmp/workdir/go/src/testing/testing.go:1742 +0x3b3

watchflakes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Status: No status
Development

No branches or pull requests

3 participants