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.

Sign up for GitHub

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

all: some pkg tests fail for -test.count>1 but pass with -test.count=1 #25520

Open
laboger opened this issue May 23, 2018 · 8 comments
Open

all: some pkg tests fail for -test.count>1 but pass with -test.count=1 #25520

laboger opened this issue May 23, 2018 · 8 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Unplanned

Comments

@laboger
Copy link
Contributor

laboger commented May 23, 2018

What version of Go are you using (go version)?

tip

Does this issue reproduce with the latest release?

yes

What operating system and processor architecture are you using (go env)?

linux ppc64le

What did you do?

Trying to run some tests multiple times to determine variations in times, but noticed that some tests fail when using count > 1 which pass for 1.

What did you expect to see?

I would expect the count not to affect whether the test passes or fails.

What did you see instead?

Failures in net/http/httputil, reflect, runtime/pprof.

2018/05/23 09:25:14 http: proxy error: EOF
2018/05/23 09:25:14 httputil: ReverseProxy read error during body copy: unexpected EOF
--- FAIL: TestDumpRequest (0.00s)
dump_test.go:224: DumpRequest #7: http: invalid Read on closed Body
2018/05/23 09:25:14 http: proxy error: EOF
2018/05/23 09:25:14 httputil: ReverseProxy read error during body copy: unexpected EOF
--- FAIL: TestDumpRequest (0.00s)
dump_test.go:224: DumpRequest #7: http: invalid Read on closed Body
2018/05/23 09:25:14 http: proxy error: EOF
2018/05/23 09:25:14 httputil: ReverseProxy read error during body copy: unexpected EOF
--- FAIL: TestDumpRequest (0.00s)
dump_test.go:224: DumpRequest #7: http: invalid Read on closed Body
2018/05/23 09:25:14 http: proxy error: EOF
2018/05/23 09:25:14 httputil: ReverseProxy read error during body copy: unexpected EOF
FAIL
FAIL net/http/httputil 0.346s

...

--- FAIL: TestCallReturnsEmpty (5.03s)
all_test.go:1706: finalizer did not run
--- FAIL: TestCallReturnsEmpty (5.01s)
all_test.go:1706: finalizer did not run
--- FAIL: TestCallReturnsEmpty (5.03s)
all_test.go:1706: finalizer did not run
FAIL
FAIL reflect 24.984s

...

--- FAIL: TestMutexProfile (0.08s)
--- FAIL: TestMutexProfile/debug=1 (0.00s)
pprof_test.go:689: received profile: --- mutex:
cycles/second=511980172
sampling period=1
14132620 2 @ 0x701f8 0x17e08c 0x68bf4
# 0x701f7 sync.(*Mutex).Unlock+0xb7 /home/boger/golang/fresh/go/src/sync/mutex.go:201
# 0x17e08b runtime/pprof.blockMutex.func1+0x3b /home/boger/golang/fresh/go/src/runtime/pprof/pprof_test.go:651

    pprof_test.go:706: "14132620 2 @ 0x701f8 0x17e08c 0x68bf4" didn't match "^\\d+ 1 @(?: 0x[[:xdigit:]]+)+"
    pprof_test.go:712: --- mutex:
            cycles/second=511980172
            sampling period=1
            14132620 2 @ 0x701f8 0x17e08c 0x68bf4
            #       0x701f7         sync.(*Mutex).Unlock+0xb7               /home/boger/golang/fresh/go/src/sync/mutex.go:201
            #       0x17e08b        runtime/pprof.blockMutex.func1+0x3b     /home/boger/golang/fresh/go/src/runtime/pprof/pprof_test.go:651

--- FAIL: TestEmptyCallStack (0.00s)
panic: pprof: NewProfile name already in use: test18836 [recovered]
panic: pprof: NewProfile name already in use: test18836

goroutine 711 [running]:
testing.tRunner.func1(0xc000694400)
/home/boger/golang/fresh/go/src/testing/testing.go:792 +0x344
panic(0x1afa40, 0xc0000906e0)
/home/boger/golang/fresh/go/src/runtime/panic.go:494 +0x1c0
runtime/pprof.NewProfile(0x1f5382, 0x9, 0x0)
/home/boger/golang/fresh/go/src/runtime/pprof/pprof.go:214 +0x210
runtime/pprof.TestEmptyCallStack(0xc000694400)
/home/boger/golang/fresh/go/src/runtime/pprof/pprof_test.go:830 +0x60
testing.tRunner(0xc000694400, 0x2022c0)
/home/boger/golang/fresh/go/src/testing/testing.go:827 +0xc0
created by testing.(*T).Run
/home/boger/golang/fresh/go/src/testing/testing.go:878 +0x2e0
FAIL runtime/pprof 77.152s

Also, I have been trying to run benchmarks for atomics multiple times and while the tests don't fail, the first run (count=1) gives me a time that looks reasonable, but results for count>1 are really high. This has me wondering if runs after the first are running with uninitialized data somewhere.

For example, the results when running -test.count=2
BenchmarkChanNonblocking-16 1000000000 3.15 ns/op
BenchmarkChanNonblocking-16 1000000000 32.7 ns/op

If I run the program for ChanNonblocking multiple times I consistently get results that are close to the first time within an expected variance.
@fraenkel
Copy link
Contributor

httputil.TestDumpRequest mutates the testcase which is why it fails with > 1.

@laboger
Copy link
Contributor Author

laboger commented May 23, 2018

The testcase failures also happen on x86. The benchmark timing issue seems to happen only on ppc64le, so I will investigate that further.

@laboger
Copy link
Contributor Author

laboger commented May 23, 2018

Found out that the benchmark timing issue was recently introduced by commit 05ca340.

Consistently reproducible using runtime test ChanNonblocking when using count > 1 on ppc64le. The first benchmark time is reasonable, subsequent times are consistently higher, 10x, 20x or more. @ALTree

@ALTree
Copy link
Member

ALTree commented May 23, 2018

I wonder if that change is not safe for benchmarks that use RunParallel. I tried a simple one with count > 1 and all the runs after the 1st are slower. Example:

go1.10:

BenchmarkF-4   	10000000	       188 ns/op
BenchmarkF-4   	10000000	       190 ns/op
BenchmarkF-4   	10000000	       189 ns/op
BenchmarkF-4   	10000000	       188 ns/op
BenchmarkF-4   	10000000	       189 ns/op

tip:

BenchmarkF-4   	10000000	       187 ns/op
BenchmarkF-4   	10000000	       198 ns/op
BenchmarkF-4   	10000000	       195 ns/op
BenchmarkF-4   	10000000	       195 ns/op
BenchmarkF-4   	10000000	       194 ns/op

ChanNonblocking also uses RunParallel.

@andybons
Copy link
Member

@bradfitz for http and httputil.
@hyangah for pprof

@andybons andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label May 23, 2018
@andybons andybons added this to the Unplanned milestone May 23, 2018
@gopherbot
Copy link

Change https://golang.org/cl/114495 mentions this issue: runtime/pprof: allow tests to run multiple times

gopherbot pushed a commit that referenced this issue May 24, 2018
@hyangah
runtime/pprof: allow tests to run multiple times
9eb2c43 
TestMutexProfile and TestEmptyCallStack couldn't run multiple times
because they mutate state in runtime (mutex profile counters and
a user-defined profile type) and test whether the state
matches what it is supposed to be after the very first run.

We fix TestMutexProfile by relaxing the expected state condition.
We fix TestEmptyCallStack by creating a new profile with a different
name every time the test runs.

For #25520

Change-Id: I8e50cd9526eb650c8989457495ff90a24ce07863
Reviewed-on: https://go-review.googlesource.com/114495
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>
@josharian
Copy link
Contributor

@ALTree seems possible. We should find out for sure about RunParallel. Will you open a new release-blocker 1.11 issue for it and do a bit of investigation? Thanks!

@ALTree ALTree mentioned this issue May 29, 2018
Closed
@ALTree
Copy link
Member

ALTree commented May 29, 2018

@josharian done in #25622. Will try to find time to look into it.

@josharian josharian changed the title test: some pkg tests fail for -test.count>1 but pass with -test.count=1 all: some pkg tests fail for -test.count>1 but pass with -test.count=1 May 31, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Unplanned
Development

No branches or pull requests
6 participants
@josharian @andybons @fraenkel @ALTree @gopherbot @laboger