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

net/http: BenchmarkClientServerParallelTLS64 sometimes reports an error #24525

Open
erifan opened this issue Mar 25, 2018 · 8 comments
Open

net/http: BenchmarkClientServerParallelTLS64 sometimes reports an error #24525

erifan opened this issue Mar 25, 2018 · 8 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone

Comments

@erifan
Copy link

erifan commented Mar 25, 2018

Please answer these questions before submitting your issue. Thanks!

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

go version devel +cc155eb

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="arm64"
GOBIN=""
GOCACHE="/home/*/.cache/go-build"
GOEXE=""
GOHOSTARCH="arm64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/username/go"
GORACE=""
GOROOT="/home/username/go-temp"
GOTMPDIR=""
GOTOOLDIR="/home/username/go-temp/pkg/tool/linux_arm64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build212786936=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I found this error in the log of our daily job (cd /src ; go test -count 3 -timeout 180m -run=^$ -bench=. ... ).

Running the command "go test -bench BenchmarkClientServerParallelTLS64" alone can also reproduce this error, but the error sometimes appears, sometimes does not appear, you may need to run it several times.

What did you expect to see?

PASS

What did you see instead?

I have seen two kinds of error messages. When executing command "go test -bench BenchmarkClientServerParallelTLS64" , the error message appears:

goos: linux
goarch: arm64
pkg: net/http
BenchmarkClientServerParallel4-32 30000 37850 ns/op 12324 B/op 88 allocs/op
BenchmarkClientServerParallel64-32 10000 307570 ns/op 13278 B/op 96 allocs/op
BenchmarkClientServerParallelTLS4-32 20000 112708 ns/op 41859 B/op 433 allocs/op
BenchmarkClientServerParallelTLS64-32 2018/03/25 13:47:49 http: TLS handshake error from 127.0.0.1:58119: read tcp 127.0.0.1:34212->127.0.0.1:58119: use of closed network connection
20000 106537 ns/op 43259 B/op 454 allocs/op
PASS
ok net/http 47.081s

When running all the benchmarks ( cd /src ; go test -count 3 -timeout 180m -run=^$ -bench=. ... ) , in addition to the above error, another error may also occur., namely:
15:10:47 BenchmarkClientServerParallelTLS64-64 Build timed out (after 10 minutes). Marking the build as aborted.
15:20:47 Build was aborted

I do not understand what the problem is. How did it come about? Can anyone explain it to me, thank you!

@mvdan mvdan added the Testing An issue that has been verified to require only test changes, not just a test failure. label Mar 25, 2018
@ALTree ALTree added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 25, 2018
@FiloSottile FiloSottile self-assigned this Mar 26, 2018
@FiloSottile FiloSottile added this to the Go1.11 milestone Mar 26, 2018
@erifan
Copy link
Author

erifan commented Mar 27, 2018

Hi, does anyone know the problem?

@mengzhuo
Copy link
Contributor

I can confirm this bug in my box
Linux hikey13 4.15-hikey #1 SMP PREEMPT Sat Mar 10 22:41:04 UTC 2018 aarch64 GNU/Linux

goos: linux                                                                         
goarch: arm64                                                                       
pkg: net/http                                                                       
BenchmarkClientServerParallelTLS64-8    2018/03/29 14:04:27 http: TLS handshake erro
r from 127.0.0.1:49120: read tcp 127.0.0.1:33467->127.0.0.1:49120: use of closed net
work connection                                                                     
2018/03/29 14:04:27 http: TLS handshake error from 127.0.0.1:49090: read tcp 127.0.0
.1:33467->127.0.0.1:49090: use of closed network connection                         
2018/03/29 14:04:27 http: TLS handshake error from 127.0.0.1:49180: read tcp 127.0.0
.1:33467->127.0.0.1:49180: use of closed network connection                         
2018/03/29 14:04:27 http: TLS handshake error from 127.0.0.1:49042: read tcp 127.0.0
.1:33467->127.0.0.1:49042: use of closed network connection                         
    2000            798913 ns/op           60430 B/op        604 allocs/op          
PASS                                                                                
ok      net/http        3.318s                                                      

@erifan
Copy link
Author

erifan commented Mar 29, 2018

@mengzhuo Yes, the issue also exists on x86.

@mengzhuo
Copy link
Contributor

@erifan I found it's related to #9661
Lots tcp connections are in TIME_WAIT status after benchmarks. TCP connection start without SO_REUSEPORT nor SO_REUSEADDR will cause this issue.

@erifan
Copy link
Author

erifan commented Mar 29, 2018

@mengzhuo I'm not sure, the error message comes from tlsConn.Handshake(), I don't know why there is a connection at this stage after the server is closed.

@erifan
Copy link
Author

erifan commented Apr 3, 2018

@FiloSottile Hi, do you know the cause of this problem? I have been investigating this issue for some time, but I still do not understand it. Can you give me some suggestions? Thanks!

@erifan
Copy link
Author

erifan commented Apr 9, 2018

This is the other error information I've observed.

15:22:49 BenchmarkClientServerParallel64-96 2000 668230 ns/op 21286 B/op 124 allocs/op
15:22:51 BenchmarkClientServerParallel64-96 3000 418305 ns/op 20977 B/op 122 allocs/op
15:22:52 BenchmarkClientServerParallelTLS4-96 2000 897250 ns/op 65399 B/op 620 allocs/op
15:22:55 BenchmarkClientServerParallelTLS4-96 2018/04/08 14:22:58 http: TLS handshake error from 127.0.0.1:38978: read tcp 127.0.0.1:39659->127.0.0.1:38978: use of closed network connection
15:22:58 2000 878092 ns/op 43781 B/op 417 allocs/op
15:22:58 BenchmarkClientServerParallelTLS4-96 1000 1015730 ns/op 72051 B/op 693 allocs/op
15:22:59 BenchmarkClientServerParallelTLS64-96 5000 345304 ns/op 78196 B/op 755 allocs/op
15:23:04 BenchmarkClientServerParallelTLS64-96 5000 211130 ns/op 71296 B/op 683 allocs/op
15:23:08 BenchmarkClientServerParallelTLS64-96 10000 1616486 ns/op 74765 B/op 731 allocs/op
15:23:27 BenchmarkServer-96 5000 313404 ns/op 2273 B/op 20 allocs/op
15:23:29 BenchmarkServer-96 5000 315469 ns/op 2273 B/op 20 allocs/op
15:23:32 BenchmarkServer-96 5000 308680 ns/op 2257 B/op 20 allocs/op
15:23:36 --- FAIL: BenchmarkClient
15:23:36 main_test.go:140: Test appears to have leaked a timing out dial:
15:23:36 internal/poll.runtime_pollWait(0xfffe56cf8750, 0x77, 0xfffe56cf8758)
15:23:36 /home/root/ci-scripts/golang/src/runtime/netpoll.go:173 +0x3c
15:23:36 internal/poll.(*pollDesc).wait(0x4011bab598, 0x77, 0x4016f55400, 0x4016f55438, 0x4014bbba01)
15:23:36 /home/root/ci-scripts/golang/src/internal/poll/fd_poll_runtime.go:85 +0x90
15:23:36 internal/poll.(*pollDesc).waitWrite(0x4011bab598, 0x4011bab500, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/internal/poll/fd_poll_runtime.go:94 +0x30
15:23:36 internal/poll.(*FD).WaitWrite(0x4011bab580, 0x40001b0010, 0x40001b0010)
15:23:36 /home/root/ci-scripts/golang/src/internal/poll/fd_unix.go:446 +0x2c
15:23:36 net.(*netFD).connect(0x4011bab580, 0x8a4200, 0x40001b0010, 0x0, 0x0, 0x89fee0, 0x4014bbbac0, 0x0, 0x0, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/fd_unix.go:152 +0x1e0
15:23:36 net.(*netFD).dial(0x4011bab580, 0x8a4200, 0x40001b0010, 0x8a4f20, 0x0, 0x8a4f20, 0x400c7e3c50, 0x5895e8, 0x401514bbf0)
15:23:36 /home/root/ci-scripts/golang/src/net/sock_posix.go:142 +0x98
15:23:36 net.socket(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x2, 0x1, 0x0, 0x0, 0x8a4f20, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/sock_posix.go:93 +0x124
15:23:36 net.internetSocket(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x8a4f20, 0x0, 0x8a4f20, 0x400c7e3c50, 0x1, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/ipsock_posix.go:141 +0xbc
15:23:36 net.doDialTCP(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x0, 0x400c7e3c50, 0x0, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/net/tcpsock_posix.go:62 +0x78
15:23:36 net.dialTCP(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x0, 0x400c7e3c50, 0x177502b8388f53, 0x221c2526, 0x40001b0010)
15:23:36 /home/root/ci-scripts/golang/src/net/tcpsock_posix.go:58 +0xb0
15:23:36 net.dialSingle(0x8a4200, 0x40001b0010, 0x4011bab500, 0x8a1d00, 0x400c7e3c50, 0x0, 0x0, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/net/dial.go:547 +0x2e0
15:23:36 net.dialSerial(0x8a4200, 0x40001b0010, 0x4011bab500, 0x4007084530, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/net/dial.go:515 +0x188
15:23:36 net.(*Dialer).DialContext(0xad7480, 0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x40091395e0, 0xf, 0x0, 0x0, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/dial.go:397 +0x4f0
15:23:36 net/http.(*Transport).dial(0x400c19c2d0, 0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x40091395e0, 0xf, 0x474a38, 0x400fb8e900, 0x200000003, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:906 +0x124
15:23:36 net/http.(*Transport).dialConn(0x400c19c2d0, 0x8a4200, 0x40001b0010, 0x0, 0x40001ec700, 0x5, 0x40091395e0, 0xf, 0x40056d9c00, 0x4003398101, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:1119 +0x23c
15:23:36 net/http.(*Transport).getConn.func4(0x400c19c2d0, 0x8a4200, 0x40001b0010, 0x40045d0a80, 0x40085acae0)
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:956 +0x44
15:23:36 created by net/http.(*Transport).getConn
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:955 +0x26c

@mmcloughlin
Copy link
Contributor

Looks like this is still an issue. Besides being a bug with this specific benchmark, it's a slight annoyance since it corrupts standard library benchmark output, therefore it does not parse correctly with standard tools (golang.org/x/perf/storage/benchfmt). For some reason the error log is also going to stdout rather than stderr. Easy to work around, but it would be nice if we could clean this up.

$ go test -run 'none^' -bench . -benchtime 10ms net/http
goos: linux
goarch: amd64
pkg: net/http
BenchmarkCookieString-8                      	   23854	       539 ns/op	     176 B/op	       1 allocs/op
...
BenchmarkClientServerParallel64-8            	     532	     77916 ns/op	   12270 B/op	      86 allocs/op
BenchmarkClientServerParallelTLS4-8          	2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57680: read tcp 127.0.0.1:40263->127.0.0.1:57680: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57672: read tcp 127.0.0.1:40263->127.0.0.1:57672: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57626: read tcp 127.0.0.1:40263->127.0.0.1:57626: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57660: write tcp 127.0.0.1:40263->127.0.0.1:57660: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57690: read tcp 127.0.0.1:40263->127.0.0.1:57690: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57658: read tcp 127.0.0.1:40263->127.0.0.1:57658: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57644: write tcp 127.0.0.1:40263->127.0.0.1:57644: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57654: write tcp 127.0.0.1:40263->127.0.0.1:57654: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42360: read tcp 127.0.0.1:33587->127.0.0.1:42360: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42436: read tcp 127.0.0.1:33587->127.0.0.1:42436: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42440: read tcp 127.0.0.1:33587->127.0.0.1:42440: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42448: read tcp 127.0.0.1:33587->127.0.0.1:42448: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42424: read tcp 127.0.0.1:33587->127.0.0.1:42424: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42442: read tcp 127.0.0.1:33587->127.0.0.1:42442: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42420: read tcp 127.0.0.1:33587->127.0.0.1:42420: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42444: read tcp 127.0.0.1:33587->127.0.0.1:42444: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42446: read tcp 127.0.0.1:33587->127.0.0.1:42446: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42422: write tcp 127.0.0.1:33587->127.0.0.1:42422: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42438: write tcp 127.0.0.1:33587->127.0.0.1:42438: use of closed network connection
      54	    196088 ns/op	  104960 B/op	    1317 allocs/op
BenchmarkClientServerParallelTLS64-8         	2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:60164: write tcp 127.0.0.1:37981->127.0.0.1:60164: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:60166: write tcp 127.0.0.1:37981->127.0.0.1:60166: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:36562: read tcp 127.0.0.1:39223->127.0.0.1:36562: use of closed network connection
      63	    253756 ns/op	  115646 B/op	    1459 allocs/op
BenchmarkServer-8                            	     156	     73795 ns/op	    2495 B/op	      20 allocs/op
...

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Development

No branches or pull requests

9 participants