gmeasure tests failing on Windows 10 with go1.19

[davidhsingyuchen]

Summary

gmeasure tests are failing on the latest master.

System information:

• Go version: go1.19 windows/amd64
• OS: Windows 10 with version 10.0.19043 N/A Build 19043 (obtained by systeminfo)

Test Output

David@David-Dell MINGW64 /d/main/dev/davidhsingyuchen/gomega (master)
$ git --no-pager log --format=%B -n 1 HEAD
v1.20.1


David@David-Dell MINGW64 /d/main/dev/davidhsingyuchen/gomega (master)
$ git rev-parse HEAD
758e947c70966b7703a740596850bcfc57af5d63
David@David-Dell MINGW64 /d/main/dev/davidhsingyuchen/gomega (master)
$ ginkgo -r -p
[1661568224] Format Suite - 53/53 specs - 11 procs +++++++++++++++++++++++++++++++++++++++++++++++++++++ SUCCESS! 784.7136ms
[1661568224] Gbytes Suite - 39/39 specs - 11 procs +++++++++++++++++++++++++++++++++++++++ SUCCESS! 182.3023ms
[1661568224] Gexec Suite - 25/25 specs - 11 procs +
------------------------------
+ [SLOW TEST] [10.350 seconds]
.CompileTestWithEnvironment compiles the specified test package with the specified env vars
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:212
------------------------------
+ [SLOW TEST] [18.195 seconds]
.CompileTestWithEnvironment a remote package compiles the specified test package with the specified env vars
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:205
------------------------------
+ [SLOW TEST] [19.359 seconds]
.CompileTest a remote package compiles the specified test package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:137
------------------------------
+ [SLOW TEST] [9.055 seconds]
.CompileTestWithEnvironment returns the environment to a good state
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:218
------------------------------
+ [SLOW TEST] [19.663 seconds]
.Build when there have been previous calls to CompileTest compiles the specified package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:23
------------------------------
+ [SLOW TEST] [20.756 seconds]
.CompileTest when there have been previous calls to CompileTest compiles the specified test package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:150
------------------------------
+ [SLOW TEST] [20.850 seconds]
.CompileTest when there have been previous calls to CompileTest and CleanupBuildArtifacts has been called compiles the specified test package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:161
------------------------------
+ [SLOW TEST] [20.978 seconds]
.Build when there have been previous calls to CompileTest and CleanupBuildArtifacts has been called compiles the specified package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:35
------------------------------
+ [SLOW TEST] [21.052 seconds]
.Build when there have been previous calls to Build compiles the specified package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:49
------------------------------
+ [SLOW TEST] [21.113 seconds]
.Build when there have been previous calls to Build and CleanupBuildArtifacts has been called compiles the specified package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:60
------------------------------
+ [SLOW TEST] [21.137 seconds]
.CompileTest when there have been previous calls to Build compiles the specified test package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:175
------------------------------
+ [SLOW TEST] [21.272 seconds]
.CompileTest when there have been previous calls to Build and CleanupBuildArtifacts has been called compiles the specified test package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:186
------------------------------
+ [SLOW TEST] [6.093 seconds]
.BuildWithEnvironment compiles the specified package with the specified env vars
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:76
------------------------------
+ [SLOW TEST] [6.786 seconds]
.BuildWithEnvironment returns the environment to a good state
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:82
------------------------------
+ [SLOW TEST] [6.911 seconds]
ExitMatcher when passed something that is not an Exiter should error
D:/main/dev/davidhsingyuchen/gomega/gexec/exit_matcher_test.go:43
------------------------------
+ [SLOW TEST] [5.710 seconds]
.CompiledTestIn appends the gopath env var
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:263
------------------------------
+ [SLOW TEST] [7.576 seconds]
ExitMatcher when passed something that is an Exiter should act normally
D:/main/dev/davidhsingyuchen/gomega/gexec/exit_matcher_test.go:33
------------------------------
+ [SLOW TEST] [6.186 seconds]
.BuildIn appends the gopath env var
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:120
------------------------------
+ [SLOW TEST] [6.149 seconds]
.BuildIn resets GOPATH to its original value
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:126
------------------------------
+ [SLOW TEST] [6.827 seconds]
ExitMatcher with no exit code should say the right things when it fails
D:/main/dev/davidhsingyuchen/gomega/gexec/exit_matcher_test.go:53
------------------------------
+ [SLOW TEST] [6.623 seconds]
ExitMatcher bailing out early should bail out early once the process exits
D:/main/dev/davidhsingyuchen/gomega/gexec/exit_matcher_test.go:106
------------------------------
+ [SLOW TEST] [6.766 seconds]
ExitMatcher with an exit code should say the right things when it fails
D:/main/dev/davidhsingyuchen/gomega/gexec/exit_matcher_test.go:75
------------------------------
+
------------------------------
+ [SLOW TEST] [50.746 seconds]
.CompiledTestIn a remote package compiles the specified test package
D:/main/dev/davidhsingyuchen/gomega/gexec/build_test.go:256
------------------------------
 SUCCESS! 1m11.9225674s
[1661568224] GHTTP Suite - 76/76 specs - 11 procs ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ SUCCESS! 51.1378ms
[1661568224] Gleak Suite - 34/34 specs - 11 procs ++++++++++++++++++++++++++++++++++ SUCCESS! 42.9262ms
[1661568224] Goroutine Suite - 14/14 specs - 11 procs ++++++++++++++ SUCCESS! 35.0336ms
[1661568224] Gmeasure Suite - 79/79 specs - 11 procs +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
------------------------------
+ [FAILED] [0.099 seconds]
Experiment Sampling [It] can cap the maximum sample time
D:/main/dev/davidhsingyuchen/gomega/gmeasure/experiment_test.go:205

  Expected
      <int>: 6
  to be within 3 of ~
      <int>: 10
  In [It] at: D:/main/dev/davidhsingyuchen/gomega/gmeasure/experiment_test.go:211
------------------------------
+ [FAILED] [0.095 seconds]
Experiment Sampling [It] can run samples in parallel
D:/main/dev/davidhsingyuchen/gomega/gmeasure/experiment_test.go:226

  Expected
      <int>: 19
  to be within 10 of ~
      <int>: 30
  In [It] at: D:/main/dev/davidhsingyuchen/gomega/gmeasure/experiment_test.go:238
------------------------------
++++++


Summarizing 2 Failures:
  [FAIL] Experiment Sampling [It] can cap the maximum sample time
  D:/main/dev/davidhsingyuchen/gomega/gmeasure/experiment_test.go:211
  [FAIL] Experiment Sampling [It] can run samples in parallel
  D:/main/dev/davidhsingyuchen/gomega/gmeasure/experiment_test.go:238

Ran 79 of 79 Specs in 0.922 seconds
FAIL! -- 77 Passed | 2 Failed | 0 Pending | 0 Skipped


Ginkgo ran 12 suites in 1m33.3438879s

There were failures detected in the following suites:
  gmeasure .\gmeasure

Test Suite Failed

[onsi]

hey there - are these happening consistently or are they flaky?

[onsi]

I'm running gmeasure locally with ginkgo -p -until-it-fails and I'm not managing to get any failures. as you can see these are timing based tests and while I've tried to have some fairly conservative limits to try to avoid flakes it looks like they might just be stressing your machine a bit too hard (they appear to be failing right at the boundary). If they're flaky (or if they always pass when you run ginkgo in serial) then I expect this is just performance related and am inclined to ignore it. But if they're consistently flaking then this might be a windows specific thing we should dig into.

[davidhsingyuchen]

Summary

Thanks for the pointer! The tests always fail regardless if they are run in serial or parallel. They do seem to consistently fail at the boundary (e.g., grep -l "<int>: 6"), which is kind of weird because my laptop is not that old, and the only demanding application that was running at the same time is browser. Detailed system information right before the tests were run can be found below (CPU usage rate ~ 15%):

$ systeminfo
<redacted>
Processor(s):              1 Processor(s) Installed.
                           [01]: Intel64 Family 6 Model 158 Stepping 10 GenuineIntel ~2592 Mhz
Total Physical Memory:     16,224 MB
Available Physical Memory: 5,194 MB

Furthermore, [FAIL] Experiment Sampling [It] can cap the maximum sample time (i.e., gomega/gmeasure/experiment_test.go:211) seems to fail every time.

All the tests are run against unmodified 061fd26.

Please let me know if any additional info is needed from my side, thanks!

Test Output

Serial

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ cat test.sh
#!/usr/bin/env bash

fails=0
for ((i=0;i<10;i++)); do
    if ! ginkgo -until-it-fails > "logs/$i.log" 2>&1; then
        ((fails++))
    fi
done
printf "%d failures" "$fails"

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ time ./test.sh
10 failures
real    0m52.634s
user    0m0.077s
sys     0m0.261s

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "D:/main/dev/onsi/gomega/gmeasure/experiment_test.go:211" logs/*.log | wc
     10      10     110

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "D:/main/dev/onsi/gomega/gmeasure/experiment_test.go:238" logs/*.log | wc
      1       1      11

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "<int>: 6" logs/*.log | wc
     10      10     110

Parallel

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ cat test.sh
#!/usr/bin/env bash

fails=0
for ((i=0;i<100;i++)); do
    if ! ginkgo -p -until-it-fails > "logs/$i.log" 2>&1; then
        ((fails++))
    fi
done
printf "%d failures" "$fails"

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ time ./test.sh
100 failures
real    5m35.485s
user    0m0.732s
sys     0m2.050s

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "D:/main/dev/onsi/gomega/gmeasure/experiment_test.go:211" logs/*.log | wc
    100     100    1190

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "D:/main/dev/onsi/gomega/gmeasure/experiment_test.go:238" logs/*.log | wc
     62      62     736

# Change the name of the log directory out-of-bound
David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "<int>: 6" logs_parallel/*.log | wc
     71      71    1484

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "<int>: 5" logs_parallel/*.log | wc
     27      27     564

David@David-Dell MINGW64 /d/main/dev/onsi/gomega/gmeasure (master)
$ grep -l "<int>: 4" logs_parallel/*.log | wc
      2       2      42