runtime: TestWindowsStackMemory flakes on windows-386-2016

[prattmic]

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

[gopherbot]

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

[alexbrainman]

• 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 #22439 (comment) . 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.

[mknyszek]

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).

[prattmic]

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

[gopherbot]

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

[alexbrainman]

@alexbrainman up for sending a patch?

Here is my CL

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

Alex

[gopherbot]

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

[alexbrainman]

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 <iant@golang.org>
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 <gobot@golang.org>
    Run-TryBot: Ian Lance Taylor <iant@google.com>
    Reviewed-by: Bryan Mills <bcmills@google.com>

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

Alex

[mknyszek]

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

[gopherbot]

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

[mknyszek]

@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.

[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]

cc @prattmic @alexbrainman

[alexbrainman]

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

go/src/runtime/testdata/testprog/syscall_windows.go

Lines 69 to 71 in 3839447

	// assumes that this process creates 1 thread for each
	// thread locked goroutine plus extra 5 threads
	// like sysmon and others

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

Thank you.

Alex

[cuonglm]

@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.

[alexbrainman]

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]

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

[gopherbot]

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

[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

[mknyszek]

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.

[gopherbot]

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]

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]

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

[rsc]

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.

[gopherbot]

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

[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