Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

x/build/cmd/coordinator: TestForeachLineAllocs fails after builders deployed #33949

Closed
toothrot opened this issue Aug 29, 2019 · 7 comments
Closed

x/build/cmd/coordinator: TestForeachLineAllocs fails after builders deployed #33949

toothrot opened this issue Aug 29, 2019 · 7 comments
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Unreleased

Comments

@toothrot
Copy link
Contributor

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.
@gopherbot gopherbot added this to the Unreleased milestone Aug 29, 2019
@gopherbot gopherbot added the Builders x/build issues (builders, bots, dashboards) label Aug 29, 2019
@toothrot toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Aug 29, 2019
@dmitshur
Copy link
Contributor

dmitshur commented Aug 29, 2019 •
edited

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
Copy link
Contributor

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 bradfitz changed the title x/build: TestForeachLineAllocs fails after builders deployed x/build/cmd/coordinator: TestForeachLineAllocs fails after builders deployed Aug 29, 2019
@bradfitz
Copy link
Contributor

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
Copy link
Contributor

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 dmitshur self-assigned this Aug 29, 2019
@dmitshur
Copy link
Contributor

🤦‍♂

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

@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Aug 29, 2019
@gopherbot
Copy link

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

@gopherbot
Copy link

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

gopherbot pushed a commit to golang/build that referenced this issue Aug 30, 2019
@dmitshur
cmd/coordinator: move adding health checkers from init to main
e21f1db 
Adding health checks at init is inflexible and earlier than neccessary.
It can cause problems for tests that run at the same time. It also
reduces code readability because it's harder to tell the relative order
of events during program initialization.

Instead, make it happen in main and inside relevant tests only.
Also pass a context through to help with cleaning up resources
after tests are done.

Updates golang/go#33949

Change-Id: Ib5ff6d93d200c273f2d344f6dd9179a7ad8e5db7
Reviewed-on: https://go-review.googlesource.com/c/build/+/192377
Run-TryBot: Dmitri Shuralyov <dmitshur@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Alexander Rakoczy <alex@golang.org>
codebien pushed a commit to codebien/build that referenced this issue Nov 13, 2019
@dmitshur @codebien
cmd/coordinator, maintner, devapp: factor out foreachLine helpers
85320a3 
It's a good idea to have an allocation test for the foreachLine helpers
to ensure their zero-allocation property isn't accidentally compromised.

Such tests turned out not to be compatible with large packages that have
many existing high-level tests, some of which start HTTP servers and/or
clients and miscellenous goroutines, and in turn leak goroutines beyond
test execution that may cause allocations in the background, leading to
inaccurate reports from testing.AllocsPerRun.

In general, a best practice is to write tests that clean up all their
resources after completion, but cmd/coordinator is large and optimized
for a single execution. Future changes may be done in a way that will
cause TestForeachLineAllocs to fail intermittently again.

As a future-proof and simple solution, just factor out the foreachLine
helpers into a small, dedicated internal package.

Fixes golang/go#33949

Change-Id: I664ec27f2b97c47a1cc88e5428152046187dbc36
Reviewed-on: https://go-review.googlesource.com/c/build/+/192680
Run-TryBot: Dmitri Shuralyov <dmitshur@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Alexander Rakoczy <alex@golang.org>
codebien pushed a commit to codebien/build that referenced this issue Nov 13, 2019
@dmitshur @codebien
cmd/coordinator: move adding health checkers from init to main
9f0c31d 
Adding health checks at init is inflexible and earlier than neccessary.
It can cause problems for tests that run at the same time. It also
reduces code readability because it's harder to tell the relative order
of events during program initialization.

Instead, make it happen in main and inside relevant tests only.
Also pass a context through to help with cleaning up resources
after tests are done.

Updates golang/go#33949

Change-Id: Ib5ff6d93d200c273f2d344f6dd9179a7ad8e5db7
Reviewed-on: https://go-review.googlesource.com/c/build/+/192377
Run-TryBot: Dmitri Shuralyov <dmitshur@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Alexander Rakoczy <alex@golang.org>
@golang golang locked and limited conversation to collaborators Aug 29, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
Builders x/build issues (builders, bots, dashboards) FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Milestone
Unreleased
Development

No branches or pull requests
4 participants
@bradfitz @toothrot @dmitshur @gopherbot