Unexpected results on CI with higher loop iterations

[ubiuser]

Hi, I added a modified version of the example tests into my project to see what results we get on our GitLab runners and they are not what I expected when the iteration runs some extra loops.

Results:

=== RUN   TestRateLimit_Example_default
    ratelimit_test.go:20: 1 0s
    ratelimit_test.go:20: 2 0s
    ratelimit_test.go:20: 3 0s
    ratelimit_test.go:20: 4 4ms
    ratelimit_test.go:20: 5 10ms
    ratelimit_test.go:20: 6 10ms
    ratelimit_test.go:20: 7 10ms
    ratelimit_test.go:20: 8 10ms
    ratelimit_test.go:20: 9 10ms
    ratelimit_test.go:20: 10 10ms
    ratelimit_test.go:20: 11 10ms
    ratelimit_test.go:20: 12 10ms
    ratelimit_test.go:20: 13 10ms
    ratelimit_test.go:20: 14 10ms
    ratelimit_test.go:20: 15 10ms
    ratelimit_test.go:20: 16 10ms
    ratelimit_test.go:20: 17 10ms
    ratelimit_test.go:20: 18 10ms
    ratelimit_test.go:20: 19 10ms
    ratelimit_test.go:20: 20 10ms
    ratelimit_test.go:20: 21 10ms
    ratelimit_test.go:20: 22 10ms
    ratelimit_test.go:20: 23 10ms
    ratelimit_test.go:20: 24 10ms
    ratelimit_test.go:20: 25 10ms
    ratelimit_test.go:20: 26 10ms
    ratelimit_test.go:20: 27 10ms
    ratelimit_test.go:20: 28 10ms
    ratelimit_test.go:20: 29 10ms
    ratelimit_test.go:20: 30 10ms
    ratelimit_test.go:20: 31 10ms
    ratelimit_test.go:20: 32 10ms
    ratelimit_test.go:20: 33 58ms
    ratelimit_test.go:20: 34 0s
    ratelimit_test.go:20: 35 0s
    ratelimit_test.go:20: 36 0s
    ratelimit_test.go:20: 37 0s
    ratelimit_test.go:20: 38 2ms
    ratelimit_test.go:20: 39 10ms
    ratelimit_test.go:20: 40 10ms
    ratelimit_test.go:20: 41 10ms
    ratelimit_test.go:20: 42 68ms
    ratelimit_test.go:20: 43 0s
    ratelimit_test.go:20: 44 0s
    ratelimit_test.go:20: 45 0s
    ratelimit_test.go:20: 46 0s
    ratelimit_test.go:20: 47 0s
    ratelimit_test.go:20: 48 2ms
    ratelimit_test.go:20: 49 10ms
--- FAIL: TestRateLimit_Example_default (0.50s)

and

=== RUN   TestRateLimit_Example_withoutSlack
    ratelimit_test.go:46: 1 10ms
    ratelimit_test.go:46: 2 10ms
    ratelimit_test.go:46: 3 10ms
    ratelimit_test.go:46: 4 55.767826ms
    ratelimit_test.go:46: 5 10ms
    ratelimit_test.go:46: 6 10ms
    ratelimit_test.go:46: 7 10ms
    ratelimit_test.go:46: 8 70.044275ms
    ratelimit_test.go:46: 9 10ms
    ratelimit_test.go:46: 10 10ms
    ratelimit_test.go:46: 11 10ms
    ratelimit_test.go:46: 12 10ms
    ratelimit_test.go:46: 13 10ms
    ratelimit_test.go:46: 14 10ms
    ratelimit_test.go:46: 15 10ms
    ratelimit_test.go:46: 16 10ms
    ratelimit_test.go:46: 17 10ms
    ratelimit_test.go:46: 18 10ms
    ratelimit_test.go:46: 19 10ms
    ratelimit_test.go:46: 20 10ms
    ratelimit_test.go:46: 21 10ms
    ratelimit_test.go:46: 22 10ms
    ratelimit_test.go:46: 23 10ms
    ratelimit_test.go:46: 24 10ms
    ratelimit_test.go:46: 25 10ms
    ratelimit_test.go:46: 26 29.903942ms
    ratelimit_test.go:46: 27 10ms
    ratelimit_test.go:46: 28 10ms
    ratelimit_test.go:46: 29 10ms
    ratelimit_test.go:46: 30 10ms
    ratelimit_test.go:46: 31 60.066856ms
    ratelimit_test.go:46: 32 10ms
    ratelimit_test.go:46: 33 10ms
    ratelimit_test.go:46: 34 10ms
    ratelimit_test.go:46: 35 10ms
    ratelimit_test.go:46: 36 59.972692ms
    ratelimit_test.go:46: 37 10ms
    ratelimit_test.go:46: 38 10ms
    ratelimit_test.go:46: 39 10ms
    ratelimit_test.go:46: 40 70.053405ms
    ratelimit_test.go:46: 41 10ms
    ratelimit_test.go:46: 42 10ms
    ratelimit_test.go:46: 43 10ms
    ratelimit_test.go:46: 44 69.93269ms
    ratelimit_test.go:46: 45 10ms
    ratelimit_test.go:46: 46 10ms
    ratelimit_test.go:46: 47 10ms
    ratelimit_test.go:46: 48 70.018764ms
    ratelimit_test.go:46: 49 10ms
--- FAIL: TestRateLimit_Example_withoutSlack (0.90s)

The modified tests are very plain, essentially I just replaced the print statement with t.Log and the loop runs more iterations.

func TestRateLimit_Example_default(t *testing.T) {
	rl := ratelimit.New(100) // per second, some slack.

	rl.Take()                         // Initialize.
	time.Sleep(time.Millisecond * 45) // Let some time pass.

	prev := time.Now()
	for i := 0; i < 50; i++ {
		now := rl.Take()
		if i > 0 {
			t.Log(i, now.Sub(prev).Round(time.Millisecond*2))
		}
		prev = now
	}

	t.Fail() // just to see the output

	// Output:
	// 1 0s
	// 2 0s
	// 3 0s
	// 4 4ms
	// 5 10ms
	// 6 10ms
	// 7 10ms
	// 8 10ms
	// 9 10ms
}

and

func TestRateLimit_Example_withoutSlack(t *testing.T) {
	rl := ratelimit.New(100, ratelimit.WithoutSlack) // per second, no slack.

	prev := time.Now()
	for i := 0; i < 50; i++ {
		now := rl.Take()
		if i > 0 {
			t.Log(i, now.Sub(prev))
		}
		prev = now
	}

	t.Fail() // just to see the output

	// Output:
	// 1 10ms
	// 2 10ms
	// 3 10ms
	// 4 10ms
	// 5 10ms
}

The project is based on Go 1.21 and is built with

ENV CGO_ENABLED=0 \
  GOOS=linux \
  GOARCH=amd64
RUN --mount=target=. \
  --mount=type=cache,target=/root/.cache/go-build \
  go build -a -tags netgo -ldflags "-w -s" -o "/bin/" ./cmd/...