go icon indicating copy to clipboard operation
go copied to clipboard

runtime: TestWindowsStackMemory flakes on windows-386-2016

Open prattmic opened this issue 2 years ago • 26 comments

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"

2023-01-17T19:55:02-d4639ec/windows-386-2016

--- FAIL: TestWindowsStackMemory (0.03s)
    crash_test.go:58: C:\Users\gopher\AppData\Local\Temp\1\go-build1812702813\testprog.exe StackMemory (27.351ms): ok
    syscall_windows_test.go:675: expected < 102400 bytes of memory per thread, got 103424
FAIL
FAIL	runtime	47.304s

Notes:

  • This is on the brand new windows-386-2016 builder.
  • The test computes the average assuming there are 100 threads. If there are actually 101 threads (the test doesn't consider sysmon...), then the average comes out to exactly 102400 bytes.

cc @mknyszek @golang/runtime @golang/windows

prattmic avatar Feb 16 '23 22:02 prattmic

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2023-01-17 19:55 windows-386-2016 go@d4639ecd runtime.TestWindowsStackMemory (log)
--- FAIL: TestWindowsStackMemory (0.03s)
    crash_test.go:58: C:\Users\gopher\AppData\Local\Temp\1\go-build1812702813\testprog.exe StackMemory (27.351ms): ok
    syscall_windows_test.go:675: expected < 102400 bytes of memory per thread, got 103424

watchflakes

gopherbot avatar Feb 24 '23 16:02 gopherbot

  • The test computes the average assuming there are 100 threads. If there are actually 101 threads (the test doesn't consider sysmon...), then the average comes out to exactly 102400 bytes.

The test was suggested by @aclements at https://github.com/golang/go/issues/22439#issuecomment-339981702 . You should be able to adjust the test to allow for a couple of extra threads to be started by runtime without TestWindowsStackMemory noticing. But we want to keep the test to prevent regressions like this one #22439.

Alex.

alexbrainman avatar Feb 26 '23 03:02 alexbrainman

In triage, I think we agree this is a test issue. @alexbrainman up for sending a patch? If not one of us will get around to it (especially if it happens again).

mknyszek avatar Mar 01 '23 20:03 mknyszek

On CL 473275: https://storage.googleapis.com/go-build-log/67b9e0cb/windows-386-2016_1815f49f.log

prattmic avatar Mar 03 '23 19:03 prattmic

Change https://go.dev/cl/473415 mentions this issue: runtime: allow for 5 more threads in TestWindowsStackMemory*

gopherbot avatar Mar 04 '23 06:03 gopherbot

@alexbrainman up for sending a patch?

Here is my CL

https://go-review.googlesource.com/c/go/+/473415

Alex

alexbrainman avatar Mar 04 '23 06:03 alexbrainman

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2023-06-21 16:11 windows-386-2016 go@03063101 runtime.TestWindowsStackMemory (log)
--- FAIL: TestWindowsStackMemory (0.03s)
    crash_test.go:58: C:\Users\gopher\AppData\Local\Temp\1\go-build3536125218\testprog.exe StackMemory (27.3413ms): ok
    syscall_windows_test.go:675: expected < 102400 bytes of memory per thread, got 102440

watchflakes

gopherbot avatar Jun 21 '23 21:06 gopherbot

2023-06-21 16:11 windows-386-2016 go@03063101 runtime.TestWindowsStackMemory

I can see that this failure happened on release-branch.go1.20 release branch - on commit

commit 03063101a2b40e78a44bdc1da84900d41a49a3ec
Author: Ian Lance Taylor <[email protected]>
Date:   Wed Jun 14 16:17:31 2023 -0700

    [release-branch.go1.20] text/template: set variables correctly in range assignment
    
    I unintentionally flipped them in CL 446795.
    
    For #56490
    For #60801
    Fixes #60802
    
    Change-Id: I57586bec052e1b2cc61513870ce24dd6ce17e56b
    Reviewed-on: https://go-review.googlesource.com/c/go/+/503576
    TryBot-Result: Gopher Robot <[email protected]>
    Run-TryBot: Ian Lance Taylor <[email protected]>
    Reviewed-by: Bryan Mills <[email protected]>

I suspect the branch does not have CL 473415 fix. Otherwise I don't have explanation for the flake 2 days ago .

Alex

alexbrainman avatar Jun 24 '23 02:06 alexbrainman

Sounds like we just need to backport the test fix to the 1.20 branch? I can handle that.

mknyszek avatar Jun 28 '23 19:06 mknyszek

Change https://go.dev/cl/506975 mentions this issue: [release-branch.go1.20] runtime: allow for 5 more threads in TestWindowsStackMemory*

gopherbot avatar Jun 28 '23 19:06 gopherbot

@gopherbot Please open backport issues for Go 1.19 and Go 1.20.

This is a test-only fix that is very small and very safe.

mknyszek avatar Jun 28 '23 20:06 mknyszek

Backport issue(s) opened: #61054 (for 1.19), #61055 (for 1.20).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://go.dev/wiki/MinorReleases.

gopherbot avatar Jun 28 '23 20:06 gopherbot

The backport issues now track the backport fixes.

mknyszek avatar Jun 28 '23 20:06 mknyszek

Change https://go.dev/cl/506976 mentions this issue: [release-branch.go1.19] runtime: allow for 5 more threads in TestWindowsStackMemory*

gopherbot avatar Jun 28 '23 20:06 gopherbot

I have just hit this again with current tip: https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-386/b8766941830696722705/overview

Re-open the issue to see if it still be problem.

cuonglm avatar Oct 18 '23 00:10 cuonglm

There's another one: https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-386/b8766892579985845249/overview

Sounds like we should increase the allowed threads from 5 to a bigger number, probably 10.

cuonglm avatar Oct 18 '23 16:10 cuonglm

cc @prattmic @alexbrainman

cuonglm avatar Oct 18 '23 17:10 cuonglm

There's another one: https://ci.chromium.org/ui/p/golang/builders/try/gotip-windows-386/b8766892579985845249/overview

Indeed.

Sounds like we should increase the allowed threads from 5 to a bigger number, probably 10.

@cuonglm why do you think 10 will work better than 5?

5 was selected as per this logic

https://github.com/golang/go/blob/3839447ac39b1c49cb14833f0832e5f934e5bf6b/src/runtime/testdata/testprog/syscall_windows.go#L69-L71

Do you think runtime changed since CL 473415 (about 6 month ago)?

Thank you.

Alex

alexbrainman avatar Oct 22 '23 03:10 alexbrainman

@cuonglm why do you think 10 will work better than 5?

5 was selected as per this logic

I saw the comment said that "sysmon and others", without explicitly said that what others are, so I assume we could increase if the test start flaking again.

cuonglm avatar Oct 22 '23 04:10 cuonglm

Interestingly it always fails on windows-386, and never on windows-amd64.

@qmuntal is it possible that there are some extra threads that are started for every single process depending on a particular system used?

For example, every Go process loads a bunch of DLLs. Is it possible that some of those DLLs start their own threads? This could even vary from system to system.

Thank you.

Alex

alexbrainman avatar Oct 22 '23 04:10 alexbrainman

I saw the comment said that "sysmon and others", without explicitly said that what others are,

I am pretty sure that sysmon is the only extra thread that is currently started - others will correct me. I added and others to future-proof my solution.

so I assume we could increase if the test start flaking again.

Yes. We could increase to 10 from 5.

Alex

alexbrainman avatar Oct 22 '23 04:10 alexbrainman

Change https://go.dev/cl/536058 mentions this issue: runtime: allow for 10 more threads in TestWindowsStackMemory*

gopherbot avatar Oct 23 '23 03:10 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2024-01-22 16:09 gotip-windows-386 go@b17bf6dd runtime.TestWindowsStackMemory (log)
=== RUN   TestWindowsStackMemory
    syscall_windows_test.go:671: C:\b\s\w\ir\x\t\go-build4036579385\testprog.exe StackMemory (28.3075ms): ok
    syscall_windows_test.go:677: expected < 102400 bytes of memory per thread, got 102884
--- FAIL: TestWindowsStackMemory (0.03s)

watchflakes

gopherbot avatar Jan 25 '24 18:01 gopherbot

Looking at this issue again, since we have another failure, our current guess is that getPagefileUsage probably includes memory other than stack memory, and it's occasionally pushing us over the edge. What exactly is being counted is unclear to us at this point, but this test seems like it's going to be inherently a bit flaky. We should dig into what exactly is being counted here.

mknyszek avatar Jan 31 '24 21:01 mknyszek

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2024-01-30 20:08 gotip-windows-386 go@b0799674 runtime.TestWindowsStackMemory (log)
=== RUN   TestWindowsStackMemory
    syscall_windows_test.go:671: C:\b\s\w\ir\x\t\go-build580327174\testprog.exe StackMemory (24.111ms): ok
    syscall_windows_test.go:677: expected < 102400 bytes of memory per thread, got 102809
--- FAIL: TestWindowsStackMemory (0.02s)

watchflakes

gopherbot avatar Feb 02 '24 18:02 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2024-08-27 17:40 gotip-windows-386 go@994d1d44 runtime.TestWindowsStackMemory (log)
=== RUN   TestWindowsStackMemory
    syscall_windows_test.go:671: C:\b\s\w\ir\x\t\go-build2480393434\testprog.exe StackMemory (21.0091ms): ok
    syscall_windows_test.go:677: expected < 102400 bytes of memory per thread, got 103144
--- FAIL: TestWindowsStackMemory (0.02s)

watchflakes

gopherbot avatar Aug 27 '24 19:08 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2024-10-23 04:43 gotip-windows-386 go@7d9802ac runtime.TestWindowsStackMemory (log)
=== RUN   TestWindowsStackMemory
    syscall_windows_test.go:671: C:\b\s\w\ir\x\t\go-build4292561115\testprog.exe StackMemory (26.2509ms): ok
    syscall_windows_test.go:677: expected < 102400 bytes of memory per thread, got 104261
--- FAIL: TestWindowsStackMemory (0.03s)

watchflakes

gopherbot avatar Oct 23 '24 05:10 gopherbot

Just got one of these in a trybot. All the failures here are just barely over 100kB. Sent CL 628795 to bump the limit to 128 kB.

rsc avatar Nov 17 '24 15:11 rsc

Change https://go.dev/cl/628795 mentions this issue: runtime: relax TestWindowsStackMemory from 100kB to 128kB

gopherbot avatar Nov 17 '24 15:11 gopherbot

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "runtime" && test == "TestWindowsStackMemory"
2024-11-17 14:32 gotip-windows-386 go@49b3ab0d runtime.TestWindowsStackMemory (log)
=== RUN   TestWindowsStackMemory
    syscall_windows_test.go:671: C:\b\s\w\ir\x\t\go-build2739463943\testprog.exe StackMemory (23.0881ms): ok
    syscall_windows_test.go:677: expected < 102400 bytes of memory per thread, got 102660
--- FAIL: TestWindowsStackMemory (0.02s)
2024-11-17 14:32 gotip-windows-386 go@9060fa5a runtime.TestWindowsStackMemory (log)
=== RUN   TestWindowsStackMemory
    syscall_windows_test.go:671: C:\b\s\w\ir\x\t\go-build2041856165\testprog.exe StackMemory (18.8138ms): ok
    syscall_windows_test.go:677: expected < 102400 bytes of memory per thread, got 106533
--- FAIL: TestWindowsStackMemory (0.02s)

watchflakes

gopherbot avatar Nov 17 '24 15:11 gopherbot