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.

Sign up for GitHub

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

Jump to bottom

x/build: LUCI windows-amd64-longtest TryBot is slow #64764

Open
bcmills opened this issue Dec 15, 2023 · 5 comments
Open

x/build: LUCI windows-amd64-longtest TryBot is slow #64764

bcmills opened this issue Dec 15, 2023 · 5 comments
Labels
Builders x/build issues (builders, bots, dashboards) NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unreleased

Comments

@bcmills
Copy link
Contributor

bcmills commented Dec 15, 2023 •
edited by cherrymui 

#!watchflakes
post <- builder ~ `(gotip|go1\.\d\d)-windows-amd64-longtest` && (`test timed out` || `SIGQUIT` || `context deadline exceeded` || status == "ABORT")

Go version

5647578230cab57e3befb9a736b045063e0156b5

What operating system and processor architecture are you using (go env)?

N/A

What did you do?

Add a gotip-windows-amd64-longtest LUCI Trybot on https://go.dev/cl/550237.

What did you expect to see?

Test results in 15 minutes or less, per #37439 (comment).

What did you see instead?

Testing on gotip-windows-amd64-longtest took 26½ minutes (http://ci.chromium.org/b/8761608988288421329).

Perhaps the builder sharding needs to be adjusted? (Maybe there are differences in machine speed or load that cause the LUCI builders to be slower than the legacy TryBots?)
@gopherbot gopherbot added the Builders x/build issues (builders, bots, dashboards) label Dec 15, 2023
@gopherbot gopherbot added this to the Unreleased milestone Dec 15, 2023
@thanm thanm added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 18, 2023
@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `(gotip|go1\.\d\d)-windows-amd64-longtest` && (`test timed out` || `SIGQUIT` || `context deadline exceeded` || status == "ABORT")
2024-01-18 22:58 x_tools-go1.21-windows-amd64-longtest tools@3458e0c5 release-branch.go1.21@2540b143 x/tools/gopls/internal/test/integration/misc.TestSignatureHelpInNonWorkspacePackage/forwarded [ABORT] (log) 
=== RUN   TestSignatureHelpInNonWorkspacePackage/forwarded
    runner.go:253: waiting on:
        Unmet: completed work "diagnosing initial workspace load" 1 times
        
        err:context deadline exceeded
        
        state:
        #### log messages (see RPC logs for full text):
        	Info: "2024/01/18 15:21:12 Handshake session update\n\tup...
        	Info: "2024/01/18 15:21:12 go info for C:\\b\\s\\w\\ir\\x...
...
panic: test timed out after 10m0s
running tests:
	TestSignatureHelpInNonWorkspacePackage (2s)
	TestSignatureHelpInNonWorkspacePackage/forwarded (1s)

goroutine 139922 [running]:
testing.(*M).startAlarm.func1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2259 +0x3b9
created by time.goFunc
	C:/b/s/w/ir/x/w/goroot/src/time/sleep.go:176 +0x2d
...
golang.org/x/tools/gopls/internal/lsp/lsprpc.(*StreamServer).ServeStream.ServerHandler.func3({0x1af54c0, 0xc001244750}, 0xc0014aa150, {0x1af5680, 0xc001244600})
	C:/b/s/w/ir/x/w/targetrepo3818468283/gopls/internal/lsp/protocol/protocol.go:158 +0x85
golang.org/x/tools/gopls/internal/lsp/lsprpc.(*StreamServer).ServeStream.handshaker.func4({0x1af54c0, 0xc001244750}, 0xc0014aa150, {0x1af5680?, 0xc001244600?})
	C:/b/s/w/ir/x/w/targetrepo3818468283/gopls/internal/lsp/lsprpc/lsprpc.go:521 +0x923
golang.org/x/tools/gopls/internal/lsp/protocol.Handlers.MustReplyHandler.func1({0x1af54c0, 0xc001244750}, 0xc004484ff0, {0x1af5680?, 0xc001244600?})
	C:/b/s/w/ir/x/w/targetrepo3818468283/internal/jsonrpc2/handler.go:35 +0xe5
golang.org/x/tools/gopls/internal/lsp/protocol.Handlers.AsyncHandler.func2.2()
	C:/b/s/w/ir/x/w/targetrepo3818468283/internal/jsonrpc2/handler.go:103 +0x96
created by golang.org/x/tools/gopls/internal/lsp/protocol.Handlers.AsyncHandler.func2 in goroutine 139712
	C:/b/s/w/ir/x/w/targetrepo3818468283/internal/jsonrpc2/handler.go:100 +0x1ed
2024-01-19 23:15 x_tools-gotip-windows-amd64-longtest tools@e1555a36 go@29cea658 x/tools/gopls/internal/test/integration/diagnostics.TestExpandWorkspaceToModule/experimental#01 [ABORT] (log) 
=== RUN   TestExpandWorkspaceToModule/experimental#01
    runner.go:253: waiting on:
        Unmet: completed work "diagnosing initial workspace load" 1 times
        
        err:context deadline exceeded
        
        state:
        #### log messages (see RPC logs for full text):
        	Info: "2024/01/22 09:27:20 go info for C:\\b\\s\\w\\ir\\x...
        
...
panic: test timed out after 10m0s
running tests:
	TestExpandWorkspaceToModule (5s)
	TestExpandWorkspaceToModule/experimental#01 (1s)

goroutine 99617 [running]:
testing.(*M).startAlarm.func1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2366 +0x385
created by time.goFunc
	C:/b/s/w/ir/x/w/goroot/src/time/sleep.go:177 +0x2d
...
golang.org/x/tools/gopls/internal/lsp/cache.(*Snapshot).WorkspaceMetadata(0xc00746fd40, {0x1104088?, 0xc0065d3d70?})
	C:/b/s/w/ir/x/w/targetrepo1202350692/gopls/internal/lsp/cache/snapshot.go:1082 +0x5e
golang.org/x/tools/gopls/internal/server.(*server).diagnose(0xc002d10200, {0x1104088, 0xc0065d3bf0}, 0xc00746fd40)
	C:/b/s/w/ir/x/w/targetrepo1202350692/gopls/internal/server/diagnostics.go:366 +0x5d8
golang.org/x/tools/gopls/internal/server.(*server).diagnoseSnapshot(0xc002d10200, 0xc00746fd40, {0x0, 0x0, 0x0}, 0x0)
	C:/b/s/w/ir/x/w/targetrepo1202350692/gopls/internal/server/diagnostics.go:223 +0x61f
golang.org/x/tools/gopls/internal/server.(*server).addFolders.func3()
	C:/b/s/w/ir/x/w/targetrepo1202350692/gopls/internal/server/general.go:328 +0x45
created by golang.org/x/tools/gopls/internal/server.(*server).addFolders in goroutine 99580
	C:/b/s/w/ir/x/w/targetrepo1202350692/gopls/internal/server/general.go:327 +0x6a9
2024-01-19 23:15 x_tools-gotip-windows-amd64-longtest tools@e1555a36 go@29cea658 x/tools/gopls/internal/test/integration/misc.TestStdlibReferences/forwarded [ABORT] (log) 
=== RUN   TestStdlibReferences/forwarded
    runner.go:253: waiting on:
        Unmet: completed work "diagnosing initial workspace load" 1 times
        
        err:context deadline exceeded
        
        state:
        #### log messages (see RPC logs for full text):
        	Info: "2024/01/22 09:27:28 Handshake session update\n\tup...
        	Info: "2024/01/22 09:27:28 go info for C:\\b\\s\\w\\ir\\x...
...
panic: test timed out after 10m0s
running tests:
	TestStdlibReferences (1s)
	TestStdlibReferences/forwarded (0s)

goroutine 103923 [running]:
testing.(*M).startAlarm.func1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2366 +0x385
created by time.goFunc
	C:/b/s/w/ir/x/w/goroot/src/time/sleep.go:177 +0x2d
...
io.copyBuffer({0x1f97e20, 0xc0047bb830}, {0x1f97a40, 0xc002adc428}, {0x0, 0x0, 0x0})
	C:/b/s/w/ir/x/w/goroot/src/io/io.go:411 +0x9d
io.Copy(...)
	C:/b/s/w/ir/x/w/goroot/src/io/io.go:388
os/exec.(*Cmd).writerDescriptor.func1()
	C:/b/s/w/ir/x/w/goroot/src/os/exec/exec.go:577 +0x34
os/exec.(*Cmd).Start.func2(0x0?)
	C:/b/s/w/ir/x/w/goroot/src/os/exec/exec.go:724 +0x2c
created by os/exec.(*Cmd).Start in goroutine 103743
	C:/b/s/w/ir/x/w/goroot/src/os/exec/exec.go:723 +0xa2b

— watchflakes

@cherrymui
Copy link
Member

I made the issue to include post-submit timeouts as well. Thanks.

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `(gotip|go1\.\d\d)-windows-amd64-longtest` && (`test timed out` || `SIGQUIT` || `context deadline exceeded` || status == "ABORT")
2024-02-02 22:08 gotip-windows-amd64-longtest go@9819d826 internal/poll.TestRead/SpecialFile [ABORT] (log) 
=== RUN   TestRead/SpecialFile
unexpected signal during runtime execution
[signal 0xc0000005 code=0x0 addr=0x11 pc=0xf1629e]

runtime stack:
runtime.throw({0x1040305?, 0x7ffc00000000?})
	C:/b/s/w/ir/x/w/goroot/src/runtime/panic.go:1011 +0x65 fp=0x7ece9fedd0 sp=0x7ece9feda0 pc=0xf1b505
runtime.sigpanic()
	C:/b/s/w/ir/x/w/goroot/src/runtime/signal_windows.go:395 +0x265 fp=0x7ece9fee18 sp=0x7ece9fedd0 pc=0xf32825
runtime/internal/atomic.(*Uintptr).Load(...)
...
created by testing.(*T).Run in goroutine 1
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x390

goroutine 50 gp=0xc000084380 m=nil [runnable]:
testing.(*T).Run.gowrap1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:1742 fp=0xc00013ffe0 sp=0xc00013ffd8 pc=0xfbbca0
runtime.goexit({})
	C:/b/s/w/ir/x/w/goroot/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc00013ffe8 sp=0xc00013ffe0 pc=0xf535a1
created by testing.(*T).Run in goroutine 16
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:1742 +0x390
2024-02-02 23:11 x_tools-go1.21-windows-amd64-longtest tools@3403ce10 release-branch.go1.21@2fdad8af x/tools/gopls/internal/test/integration/misc.TestWorkspaceSymbolMissingMetadata/experimental [ABORT] (log) 
=== RUN   TestWorkspaceSymbolMissingMetadata/experimental
    runner.go:253: waiting on:
        Unmet: completed work "diagnosing initial workspace load" 1 times
        
        err:context deadline exceeded
        
        state:
        #### log messages (see RPC logs for full text):
        	Info: "2024/02/02 15:31:43 go info for C:\\b\\s\\w\\ir\\x...
        
...
panic: test timed out after 10m0s
running tests:
	TestWorkspaceSymbolMissingMetadata (2s)
	TestWorkspaceSymbolMissingMetadata/experimental (0s)

goroutine 155146 [running]:
testing.(*M).startAlarm.func1()
	C:/b/s/w/ir/x/w/goroot/src/testing/testing.go:2259 +0x3b9
created by time.goFunc
	C:/b/s/w/ir/x/w/goroot/src/time/sleep.go:176 +0x2d
...
golang.org/x/tools/gopls/internal/debug.(*Instance).Serve.func1()
	C:/b/s/w/ir/x/w/targetrepo555460451/gopls/internal/debug/serve.go:483 +0xb85
created by golang.org/x/tools/gopls/internal/debug.(*Instance).Serve in goroutine 9944
	C:/b/s/w/ir/x/w/targetrepo555460451/gopls/internal/debug/serve.go:444 +0x45b

goroutine 155142 [chan send]:
golang.org/x/tools/go/packages.goListDriver.func1()
	C:/b/s/w/ir/x/w/targetrepo555460451/go/packages/golist.go:155 +0x1d0
created by golang.org/x/tools/go/packages.goListDriver in goroutine 155154
	C:/b/s/w/ir/x/w/targetrepo555460451/go/packages/golist.go:151 +0x2ea

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `(gotip|go1\.\d\d)-windows-amd64-longtest` && (`test timed out` || `SIGQUIT` || `context deadline exceeded` || status == "ABORT")
2024-03-11 18:35 gotip-windows-amd64-longtest go@edbb5a13 runtime:mayMoreStackPreempt.TestNetpollDeadlock (log) 
=== RUN   TestNetpollDeadlock
=== PAUSE TestNetpollDeadlock
=== CONT  TestNetpollDeadlock
    exec.go:193: test timed out while running command: C:\b\s\w\ir\x\t\go-build2767286069\testprognet.exe NetpollDeadlock
    crash_test.go:506: C:\b\s\w\ir\x\t\go-build2767286069\testprognet.exe NetpollDeadlock: exit status 1
    crash_test.go:509: output does not start with "done\n":
        dialing
--- FAIL: TestNetpollDeadlock (2586.49s)
2024-03-12 17:04 gotip-windows-amd64-longtest go@5eb87c39 runtime:mayMoreStackPreempt.TestNetpollDeadlock (log) 
=== RUN   TestNetpollDeadlock
=== PAUSE TestNetpollDeadlock
=== CONT  TestNetpollDeadlock
    crash_test.go:170: running C:\b\s\w\ir\x\w\goroot\bin\go.exe build -o C:\b\s\w\ir\x\t\go-build1475190012\testprognet.exe
    crash_test.go:176: built testprognet in 2.1601831s
    exec.go:193: test timed out while running command: C:\b\s\w\ir\x\t\go-build1475190012\testprognet.exe NetpollDeadlock
    crash_test.go:506: C:\b\s\w\ir\x\t\go-build1475190012\testprognet.exe NetpollDeadlock: exit status 1
    crash_test.go:509: output does not start with "done\n":
        dialing
--- FAIL: TestNetpollDeadlock (2590.73s)

— watchflakes

@gopherbot
Copy link

Found new dashboard test flakes for:

#!watchflakes
post <- builder ~ `(gotip|go1\.\d\d)-windows-amd64-longtest` && (`test timed out` || `SIGQUIT` || `context deadline exceeded` || status == "ABORT")
2024-03-13 18:22 gotip-windows-amd64-longtest go@38723f2b runtime:mayMoreStackPreempt.TestNetpollDeadlock (log) 
=== RUN   TestNetpollDeadlock
=== PAUSE TestNetpollDeadlock
=== CONT  TestNetpollDeadlock
    exec.go:193: test timed out while running command: C:\b\s\w\ir\x\t\go-build1389385579\testprognet.exe NetpollDeadlock
    crash_test.go:506: C:\b\s\w\ir\x\t\go-build1389385579\testprognet.exe NetpollDeadlock: exit status 1
    crash_test.go:509: output does not start with "done\n":
        dialing
--- FAIL: TestNetpollDeadlock (2590.85s)

— watchflakes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Builders x/build issues (builders, bots, dashboards) NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Test Flakes
Status: No status
Milestone
Unreleased
Development

No branches or pull requests
4 participants
@bcmills @gopherbot @thanm @cherrymui