Go: x/build/cmd/coordinator: TestForeachLineAllocs fails after builders deployed

[toothrot]

While testing if #33928 was resolved, the cmd/coordinator/status_test.go:TestForEachLineAllocs test started failing with significantly more allocs than the threshold.

From: https://go-review.googlesource.com/c/build/+/192103/1#message-cfc755e443676448b10e0301816edb916bd386ac

5 of 9 TryBots failed:
Failed on linux-amd64: https://storage.googleapis.com/go-build-log/e87fe0f1/linux-amd64_b554d822.log
Failed on linux-386: https://storage.googleapis.com/go-build-log/e87fe0f1/linux-386_bdf42483.log
Failed on linux-amd64 (Go 1.11.x): https://storage.googleapis.com/go-build-log/83bd8812/linux-amd64_551b9063.log
Failed on linux-amd64 (Go 1.12.x): https://storage.googleapis.com/go-build-log/61a5d114/linux-amd64_e60c908d.log
Failed on linux-amd64-race: https://storage.googleapis.com/go-build-log/e87fe0f1/linux-amd64-race_e318c3fa.log

2019/08/29 17:09:48 Starting new trybot set for {build master I6f05da2186b38dc8056081252563a82c50f0ce05 a62e6a3ab11cc9cc2d9e22a50025dd33fc35d22f}
--- FAIL: TestForeachLineAllocs (0.21s)
    status_test.go:118: allocs = 220
FAIL

Failing test:

func TestForeachLineAllocs(t *testing.T) {
    v := bytes.Repeat([]byte(`line 1
line 2
line 3


after two blank lines
last line`), 1000)
    allocs := testing.AllocsPerRun(1000, func() {
        foreachLine(v, func([]byte) error { return nil })
    })
    if allocs > 0.1 {
        t.Errorf("allocs = %v", allocs)
    }
}

The test in question was introduced in https://go-review.googlesource.com/c/build/+/185981. It looks like it is mistakenly expecting a non-integral value from testing.AllocsPerRun, which returns a float64 that is actually always an integral value.

It's still surprising that allocs would be as high as 220, as locally testing.AllocsPerRun returns 0 when I run this test on linux-amd64 go1.13rc2. I also tested on older releases of Go, and cannot reproduce this failure localy.

[dmitshur]

I can't reproduce locally on darwin/amd64, but I can reproduce on linux/amd64 in a GCE VM with Go 1.12.9:

$ go version
go version go1.12.9 linux/amd64
$ go test -count=1 -v -run=TestForeachLineAllocs golang.org/x/build/cmd/coordinator
=== RUN   TestForeachLineAllocs
--- FAIL: TestForeachLineAllocs (0.18s)
    status_test.go:118: allocs = 106
FAIL
FAIL    golang.org/x/build/cmd/coordinator  0.334s

The test in question was introduced in https://go-review.googlesource.com/c/build/+/185981. It looks like it is mistakenly expecting a non-integral value from testing.AllocsPerRun, which returns a float64 that is actually always an integral value.

I understand it's intentional. It's a check that there are absolutely zero allocations. The 0.1 value is an arbitrary number that's greater than 0.

See https://github.com/bradfitz/iter/blob/33e6a9893b0c090a6ba5a4227a98c4145c61d09a/iter_test.go#L25-L34 for another example. /cc @bradfitz

[bradfitz]

That was old defensive style prior to this:

https://golang.org/doc/go1.2#minor_library_changes ...

the AllocsPerRun function now quantizes the return value to an integer (although it still has type float64), to round off any error caused by initialization and make the result more repeatable.

[bradfitz]

Interestingly, it only fails the first few iterations:

$ go test  -v -run=TestForeachLineAllocs -memprofile=prof.mem -count=100
=== RUN   TestForeachLineAllocs
--- FAIL: TestForeachLineAllocs (0.12s)
    status_test.go:118: allocs = 164
=== RUN   TestForeachLineAllocs
--- FAIL: TestForeachLineAllocs (0.12s)
    status_test.go:118: allocs = 128
=== RUN   TestForeachLineAllocs
--- PASS: TestForeachLineAllocs (0.08s)
=== RUN   TestForeachLineAllocs
--- PASS: TestForeachLineAllocs (0.08s)
=== RUN   TestForeachLineAllocs
--- PASS: TestForeachLineAllocs (0.08s)
=== RUN   TestForeachLineAllocs
--- PASS: TestForeachLineAllocs (0.08s)
=== RUN   TestForeachLineAllocs
--- PASS: TestForeachLineAllocs (0.08s)
=== RUN   TestForeachLineAllocs
--- PASS: TestForeachLineAllocs (0.08s)
=== RUN   TestForeachLineAllocs

Same behavior with Go 1.12.

I think there's a goroutine running concurrently with this test and that goroutine is allocating, confusing AllocsPerRun.

[bradfitz]

Yeah, @dmitshur's https://go-review.googlesource.com/c/build/+/185981 starts up a goroutine that HTTP fetches tip.golang.org in init, even during tests.

[dmitshur]

🤦‍♂

Nice find, Brad. Good news is that it's not a regression in bytes.IndexByte starting to allocate unnecessarily! I'll send a fix.

[gopherbot]

Change https://golang.org/cl/192377 mentions this issue: cmd/coordinator: move adding health checkers from init to main

[gopherbot]

Change https://golang.org/cl/192680 mentions this issue: cmd/coordinator, maintner, devapp: factor out foreachLine helpers