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

x/tools/cmd/fiximports: frequent TestDryRun and TestFixImports timeouts on plan9-arm since 2021-11-12 #50775

Open
bcmills opened this issue Jan 24, 2022 · 9 comments
Labels
arch-arm Issues solely affecting the 32-bit arm architecture. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Plan9 Tools This label describes issues relating to any tools in the x/tools repository.
Milestone

Comments

@bcmills
Copy link
Contributor

bcmills commented Jan 24, 2022

#!watchflakes
post <- builder ~ `^plan9` && pkg == "golang.org/x/tools/cmd/fiximports" && (test == "TestDryRun" || test == "TestFixImports")

greplogs --dashboard -md -l -e 'panic: test timed out.*\n(?:.*\n)*golang\.org/x/tools/cmd/fiximports\.TestDryRun' --since=2021-01-01

2022-01-21T16:59:19-9f83dd3-9eba5ff/plan9-arm
2022-01-19T14:58:28-a8c7459-2a061fd/plan9-arm
2022-01-18T14:56:19-f29bdf1-5b3ebc8/plan9-arm
2022-01-14T21:54:39-f29bdf1-3b5eec9/plan9-arm
2022-01-13T18:06:33-68b574a-4fa6e33/plan9-arm
2022-01-13T17:30:17-68b574a-2423912/plan9-arm
2022-01-11T17:13:50-d7a4bb4-1abe9c1/plan9-arm
2022-01-11T14:03:54-d7a4bb4-90a8482/plan9-arm
2022-01-10T19:19:50-f234b3d-933f668/plan9-arm
2022-01-04T22:05:15-15409b5-e39ab9b/plan9-arm
2021-12-28T19:10:34-2c49d4f-b357b05/plan9-arm
2021-12-16T22:41:31-8d38310-1387b5e/plan9-arm
2021-12-16T21:08:09-8d38310-ae695cd/plan9-arm
2021-12-10T19:26:50-27fc764-766f89b/plan9-arm
2021-12-09T15:47:16-27fc764-61ba0bc/plan9-arm
2021-12-08T23:00:01-3fca6a0-f5ddd94/plan9-arm
2021-12-07T00:03:34-feb39d0-79b425e/plan9-arm
2021-12-06T17:34:53-feb39d0-2cb9042/plan9-arm
2021-12-06T16:11:25-feb39d0-f8a8a73/plan9-arm
2021-12-04T11:59:35-c882a49-1876b38/plan9-arm
2021-12-03T16:24:32-e212aff-29483b3/plan9-arm
2021-12-03T14:28:11-e212aff-a174638/plan9-arm
2021-12-02T23:34:26-e212aff-5f65520/plan9-arm
2021-12-01T19:09:57-d99d6fa-0103fd2/plan9-arm
2021-12-01T18:47:44-3c63f30-08ecdf7/plan9-arm
2021-12-01T15:58:46-615f9a6-029dfbc/plan9-arm
2021-12-01T15:05:46-615f9a6-0e1d553/plan9-arm
2021-11-30T18:49:39-2c9b078-5f63f16/plan9-arm
2021-11-30T18:09:02-2c9b078-931d80e/plan9-arm
2021-11-29T22:57:42-6e52f51-3ca57c7/plan9-arm
2021-11-29T20:12:13-6e52f51-f598e29/plan9-arm
2021-11-29T16:08:23-a618923-a59ab29/plan9-arm
2021-11-22T23:51:43-c2c92fd-83bfed9/plan9-arm
2021-11-22T21:22:40-c2c92fd-f13fcd9/plan9-arm
2021-11-22T16:53:57-d0c7211-cd0bf38/plan9-arm
2021-11-19T22:35:28-d0c7211-b31dda8/plan9-arm
2021-11-18T16:18:50-43b469a-feb330d/plan9-arm
2021-11-17T21:26:25-43b469a-0440fb8/plan9-arm
2021-11-17T19:51:32-43b469a-9a33945/plan9-arm
2021-11-17T19:16:04-43b469a-0981724/plan9-arm
2021-11-17T17:03:06-7d6c71f-4083a6f/plan9-arm
2021-11-16T14:26:19-1a3081d-bddb79f/plan9-arm
2021-11-15T15:42:24-49ce184-ce4a275/plan9-arm
2021-11-14T17:38:42-49ce184-5337e53/plan9-arm
2021-11-12T20:20:57-fda06c1-76fbd61/plan9-arm

I assume that this has something to do with filesystem performance, but the difference is several orders of magnitude. This test runs in about 500ms on my Linux workstation, and it's timing out after 10 minutes on plan9-arm. 😅

(CC @millerresearch)

@bcmills bcmills added OS-Plan9 arch-arm Issues solely affecting the 32-bit arm architecture. labels Jan 24, 2022
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Jan 24, 2022
@gopherbot gopherbot added this to the Unreleased milestone Jan 24, 2022
@gopherbot
Copy link

Change https://golang.org/cl/380495 mentions this issue: cmd/fiximports: skip TestDryRun on plan9-arm

gopherbot pushed a commit to golang/tools that referenced this issue Jan 24, 2022
For golang/go#50775.

Change-Id: I229263c840f406926b1f7c91de2400d4a18f3e16
Reviewed-on: https://go-review.googlesource.com/c/tools/+/380495
Trust: Bryan Mills <bcmills@google.com>
Reviewed-by: Daniel Martí <mvdan@mvdan.cc>
@mknyszek mknyszek added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 24, 2022
@millerresearch
Copy link
Contributor

This test runs in about 500ms on my Linux workstation, and it's timing out after 10 minutes on plan9-arm

I've been running TestDryRun in a loop on the least powerful of the current plan9-arm builders (Pi 3B+ with 1GB RAM). It takes about 21 seconds each time. Running the whole fiximports.test is about 145 seconds. So whatever's causing the timeout is not very repeatable. Needs investigation.

@millerresearch
Copy link
Contributor

I can't replicate this by running the fiximports test on its own - it never takes more than 25 seconds. The problem must be an interaction with other tests being run in parallel.
I've just tried running go test x/tools/cmd/... and found that fiximports.test in that context took 425 seconds. Most of the time it was running in parallel with guru.test (487420K virtual memory size) and stringer.test (a more normal 276804K virtual memory). Physical memory was tight but not swapping. The finish message for guru.test never appeared, and after a while it became apparent that all subcommands had terminated but the go test command was deadlocked. I sent it a kill signal to get a stack trace, which looks like this:

goroutine 0 [idle]:
runtime.plan9_semacquire()
	/sys/lib/go1.17/src/runtime/sys_plan9_arm.s:120 +0x8
runtime.semasleep(0xffffffffffffffff)
	/sys/lib/go1.17/src/runtime/os_plan9.go:484 +0x68
runtime.notesleep(0x112ac0b4)
	/sys/lib/go1.17/src/runtime/lock_sema.go:182 +0x88
runtime.mPark()
	/sys/lib/go1.17/src/runtime/proc.go:1441 +0x20
runtime.stopm()
	/sys/lib/go1.17/src/runtime/proc.go:2408 +0x78
runtime.findrunnable()
	/sys/lib/go1.17/src/runtime/proc.go:2984 +0x9e4
runtime.schedule()
	/sys/lib/go1.17/src/runtime/proc.go:3367 +0x2ac
runtime.park_m(0x10c00780)
	/sys/lib/go1.17/src/runtime/proc.go:3516 +0x18c
runtime.mcall()
	/sys/lib/go1.17/src/runtime/asm_arm.s:266 +0x48

goroutine 1 [semacquire, 15 minutes]:
sync.runtime_Semacquire(0x111a8f48)
	/sys/lib/go1.17/src/runtime/sema.go:56 +0x34
sync.(*WaitGroup).Wait(0x111a8f40)
	/sys/lib/go1.17/src/sync/waitgroup.go:130 +0x94
cmd/go/internal/work.(*Builder).Do(0x10dacae0, {0x5dd1bc, 0x10c28394}, 0x111a2630)
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:208 +0x3c4
cmd/go/internal/test.runTest({0x5dd1bc, 0x10c28394}, 0x829068, {0x10c20070, 0x1, 0x1})
	/sys/lib/go1.17/src/cmd/go/internal/test/test.go:828 +0x2384
main.invoke(0x829068, {0x10c20068, 0x2, 0x2})
	/sys/lib/go1.17/src/cmd/go/main.go:216 +0x2f0
main.main()
	/sys/lib/go1.17/src/cmd/go/main.go:173 +0x914

goroutine 2894 [select, 7 minutes]:
cmd/go/internal/work.(*Builder).Do.func3(0x110f4a48, 0x111a8f40, 0x10dacae0, 0x111f86d0)
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:189 +0xf4
created by cmd/go/internal/work.(*Builder).Do
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:185 +0x3a4

goroutine 3281 [chan receive, 15 minutes]:
cmd/go/internal/base.processSignals.func1(0x1130ea80)
	/sys/lib/go1.17/src/cmd/go/internal/base/signal.go:21 +0x24
created by cmd/go/internal/base.processSignals
	/sys/lib/go1.17/src/cmd/go/internal/base/signal.go:20 +0x74

goroutine 3264 [syscall, 15 minutes]:
os/signal.signal_recv()
	/sys/lib/go1.17/src/runtime/sigqueue_plan9.go:116 +0x74
os/signal.loop()
	/sys/lib/go1.17/src/os/signal/signal_plan9.go:27 +0x14
created by os/signal.Notify.func1.1
	/sys/lib/go1.17/src/os/signal/signal.go:151 +0x30

goroutine 2892 [runnable]:
syscall.Syscall(0x2a, 0x10ecb080, 0x13a48000, 0x73)
	/sys/lib/go1.17/src/syscall/asm_plan9_arm.s:16 +0x8
syscall.stat({0x10ecb020, 0x21}, {0x13a48000, 0x73, 0x73})
	/sys/lib/go1.17/src/syscall/zsyscall_plan9_arm.go:115 +0xfc
syscall.Stat({0x10ecb020, 0x21}, {0x13a48000, 0x73, 0x73})
	/sys/lib/go1.17/src/syscall/syscall_plan9.go:400 +0x74
os.dirstat({0x4b4ef8, 0x10ded804})
	/sys/lib/go1.17/src/os/stat_plan9.go:62 +0x140
os.statNolog({0x10ecb020, 0x21})
	/sys/lib/go1.17/src/os/stat_plan9.go:95 +0x34
os.lstatNolog(...)
	/sys/lib/go1.17/src/os/stat_plan9.go:104
os.Lstat({0x10ecb020, 0x21})
	/sys/lib/go1.17/src/os/stat.go:22 +0x38
path/filepath.walkSymlinks({0x10c30380, 0x30})
	/sys/lib/go1.17/src/path/filepath/symlink.go:84 +0x168
path/filepath.evalSymlinks(...)
	/sys/lib/go1.17/src/path/filepath/symlink_unix.go:7
path/filepath.EvalSymlinks({0x10c30380, 0x30})
	/sys/lib/go1.17/src/path/filepath/path.go:235 +0x24
cmd/go/internal/search.InDir({0x11096feb, 0x4}, {0x10c30380, 0x30})
	/sys/lib/go1.17/src/cmd/go/internal/search/search.go:587 +0x120
cmd/go/internal/test.computeTestInputsID(0x10c938c0, {0x11a68000, 0xd71589, 0xd7158a})
	/sys/lib/go1.17/src/cmd/go/internal/test/test.go:1519 +0x630
cmd/go/internal/test.(*runCache).saveOutput(0x111c8730, 0x10c938c0)
	/sys/lib/go1.17/src/cmd/go/internal/test/test.go:1642 +0x2f0
cmd/go/internal/test.(*runCache).builderRunTest(0x111c8730, 0x10dacae0, {0x5dd1bc, 0x10c28394}, 0x10c938c0)
	/sys/lib/go1.17/src/cmd/go/internal/test/test.go:1282 +0x1334
cmd/go/internal/work.(*Builder).Do.func2({0x5dd1bc, 0x10c28394}, 0x10c938c0)
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:137 +0x4fc
cmd/go/internal/work.(*Builder).Do.func3(0x110f4a48, 0x111a8f40, 0x10dacae0, 0x111f86d0)
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:199 +0x9c
created by cmd/go/internal/work.(*Builder).Do
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:185 +0x3a4

goroutine 2893 [select, 7 minutes]:
cmd/go/internal/work.(*Builder).Do.func3(0x110f4a48, 0x111a8f40, 0x10dacae0, 0x111f86d0)
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:189 +0xf4
created by cmd/go/internal/work.(*Builder).Do
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:185 +0x3a4

goroutine 2974 [select, 7 minutes]:
cmd/go/internal/work.(*Builder).Do.func3(0x110f4a48, 0x111a8f40, 0x10dacae0, 0x111f86d0)
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:189 +0xf4
created by cmd/go/internal/work.(*Builder).Do
	/sys/lib/go1.17/src/cmd/go/internal/work/exec.go:185 +0x3a4

The symptom may be a timeout in fiximports, but I think the underlying problem is a deadlock somewhere else.

@millerresearch
Copy link
Contributor

A bit more information.

In the above test, the reason guru.test was taking so long was that I hadn't used the -short flag. And I think go test wasn't deadlocked: it was just busy attempting to cache the test inputs and results. Computing the TestInputsID takes a stupendously long time because it's going through a testlog.txt which lists 357000 filenames, each requiring a stat call after being expanded by filepath.EvalSymlinks (which itself requires a stat call per filename component). In fact there are only 5841 unique lines in the testlog.txt, so sorting the list and eliminating duplicates would speed that up quite a bit. Also on Plan 9 (are there any other OSs without symlinks?) implementing EvalSymlinks as a simple call to filepath.Clean instead of pointlessly calling stat on each component would also be helpful.

Unfortunately that doesn't get any closer to explaining why fiximports.test is timing out on the builder.

@bcmills
Copy link
Contributor Author

bcmills commented Jan 26, 2022

In fact there are only 5841 unique lines in the testlog.txt, so sorting the list and eliminating duplicates would speed that up quite a bit.

Ooh, that's a very useful observation for #26562!

Also on Plan 9 (are there any other OSs without symlinks?) implementing EvalSymlinks as a simple call to filepath.Clean instead of pointlessly calling stat on each component would also be helpful.

To my knowledge there are no other OSs supported by Go that lack symlinks entirely. (Windows has supported them since Vista, and in Windows 10 they don't even require elevated privileges as of build 14972.)

If you'd like to send a CL for plan9, I'd be happy to review it when the tree opens for Go 1.19. I think it should be as simple as adding src/path/filepath/symlink_plan9.go and updating the build constraint for symlink_unix.go:
https://cs.opensource.google/go/go/+/master:src/path/filepath/symlink_unix.go;l=1;drc=f229e7031a6efb2f23241b5da000c3b3203081d6

@bcmills
Copy link
Contributor Author

bcmills commented Apr 7, 2022

With TestDryRun skipped, we're still hitting frequent timeouts for this package:

greplogs --dashboard -md -l -e 'panic: test timed out.*\n(?:.*\n)*golang\.org/x/tools/cmd/fiximports\.Test' --since=2022-01-25

2022-04-07T10:41:34-b3e0236-3a0cda4/plan9-arm
2022-04-07T05:42:16-b3e0236-870256e/plan9-arm
2022-04-06T22:27:40-b3e0236-9a6acc8/plan9-arm
2022-04-06T22:00:21-b3e0236-81ae993/plan9-arm
2022-04-06T18:19:46-6731659-5bb2628/plan9-arm
2022-04-04T04:04:18-153e30b-884e75f/plan9-arm
2022-04-03T23:48:16-153e30b-ba6df85/plan9-arm
2022-04-01T01:41:42-cda13e2-bb2b16d/plan9-arm
2022-03-31T06:40:26-b9a4807-ebe624d/plan9-arm
2022-03-30T18:25:30-8e193c2-ca1e509/plan9-arm
2022-03-30T17:49:40-8e193c2-c05c0ca/plan9-arm
2022-03-29T15:43:06-e693fb4-ae9ce82/plan9-arm
2022-03-29T01:48:39-e693fb4-94727be/plan9-arm
2022-03-29T00:02:55-e693fb4-9a9bd10/plan9-arm
2022-03-28T19:58:45-e693fb4-42ca444/plan9-arm
2022-03-24T03:55:46-9fd677e-9058080/plan9-arm
2022-03-22T16:51:29-c717623-63ea27e/plan9-arm
2022-03-22T15:16:23-c717623-eca0d44/plan9-arm
2022-03-22T13:07:38-c717623-2da1e47/plan9-arm
2022-03-18T13:39:41-5ea13d0-12eca21/plan9-arm
2022-03-18T09:40:34-779dfa4-4432059/plan9-arm
2022-03-17T13:53:34-877ec07-c379c3d/plan9-arm
2022-03-16T22:16:36-85d68bc-ed4db86/plan9-arm
2022-03-16T21:09:13-d67eab4-ed4db86/plan9-arm
2022-03-16T07:03:20-77aa08b-5fd0ed7/plan9-arm
2022-03-14T20:05:58-dff7c5f-41fe746/plan9-arm
2022-03-11T00:42:08-ee31f70-9743e9b/plan9-arm
2022-03-10T23:20:43-ee31f70-5003ed8/plan9-arm
2022-03-10T21:10:30-613589d-914195c/plan9-arm
2022-03-10T19:52:31-613589d-2e46a0a/plan9-arm
2022-03-10T16:06:29-1670aad-1cf6770/plan9-arm
2022-03-10T09:12:04-1670aad-5a040c5/plan9-arm
2022-03-09T23:21:06-1670aad-3a5e3d8/plan9-arm
2022-03-09T21:31:58-b105aac-a987aaf/plan9-arm
2022-03-09T21:08:21-b105aac-7026eeb/plan9-arm
2022-03-09T17:16:12-03d333a-7026eeb/plan9-arm
2022-03-08T15:18:31-b59c441-7fd9564/plan9-arm
2022-03-08T00:44:45-b59c441-0043c1e/plan9-arm
2022-03-07T20:22:24-b59c441-20dd9a4/plan9-arm
2022-03-04T18:26:08-0eabed7-ca384f7/plan9-arm
2022-03-04T15:48:03-19fe2d7-46afa89/plan9-arm
2022-03-04T01:18:57-3ce7728-81767e2/plan9-arm
2022-03-03T22:52:16-3ce7728-4f80943/plan9-arm
2022-03-02T22:41:01-e43402d-bcb89fc/plan9-arm
2022-03-02T18:47:53-4a5e7f0-986b04c/plan9-arm
2022-03-01T23:49:01-ffa170d-6da16b6/plan9-arm
2022-03-01T21:32:50-ffa170d-f4722d8/plan9-arm
2022-03-01T21:32:50-ffa170d-b0db2f0/plan9-arm
2022-02-22T17:36:43-3e31058-d17b65f/plan9-arm
2022-02-11T05:11:58-c0b9fb5-e50f0f3/plan9-arm
2022-02-08T08:41:09-164402d-c856fbf/plan9-arm

By eyeball, ~all of the recent timeouts appear to be in TestFixImports.

@bcmills bcmills changed the title x/tools/cmd/fiximports: frequent TestDryRun timeouts on plan9-arm since 2021-11-12 x/tools/cmd/fiximports: frequent TestDryRun and TestFixImportrs timeouts on plan9-arm since 2021-11-12 Apr 7, 2022
@gopherbot
Copy link

Change https://go.dev/cl/398817 mentions this issue: cmd/fiximports: skip TestFixImports on plan9-arm

gopherbot pushed a commit to golang/tools that referenced this issue Apr 7, 2022
For golang/go#50775.

Change-Id: Ia7d99e9e7b007af3fa35332f0385949867e975eb
Reviewed-on: https://go-review.googlesource.com/c/tools/+/398817
Trust: Bryan Mills <bcmills@google.com>
Run-TryBot: Bryan Mills <bcmills@google.com>
gopls-CI: kokoro <noreply+kokoro@google.com>
Reviewed-by: Suzy Mueller <suzmue@golang.org>
@gopherbot
Copy link

Change https://go.dev/cl/404954 mentions this issue: path/filepath: simplify EvalSymlinks for plan9

gopherbot pushed a commit that referenced this issue May 9, 2022
Plan 9 doesn't have symbolic links, so EvalSymlinks can be simplified
just to check validity of the path and call Clean. This saves a lot
of redundant file system activity.

Updates #50775

Change-Id: I84c24ef1d5e6e38fd19df2d37c72fbf883f0140d
Reviewed-on: https://go-review.googlesource.com/c/go/+/404954
Reviewed-by: Bryan Mills <bcmills@google.com>
Reviewed-by: Dmitri Shuralyov <dmitshur@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: David du Colombier <0intro@gmail.com>
Reviewed-by: David du Colombier <0intro@gmail.com>
@dmitshur

This comment was marked as resolved.

@bcmills bcmills changed the title x/tools/cmd/fiximports: frequent TestDryRun and TestFixImportrs timeouts on plan9-arm since 2021-11-12 x/tools/cmd/fiximports: frequent TestDryRun and TestFixImports timeouts on plan9-arm since 2021-11-12 Mar 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
arch-arm Issues solely affecting the 32-bit arm architecture. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. OS-Plan9 Tools This label describes issues relating to any tools in the x/tools repository.
Projects
Status: No status
Development

No branches or pull requests

5 participants