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

[bcmills]

#!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)

[gopherbot]

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

[millerresearch]

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]

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]

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]

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]

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.