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, x/net/http2: small delays trigger timeout #61545

Closed
Harpal-7 opened this issue Jul 24, 2023 · 4 comments
Closed

net/http, x/net/http2: small delays trigger timeout #61545

Harpal-7 opened this issue Jul 24, 2023 · 4 comments
Labels
WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@Harpal-7
Copy link

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

go version go1.19.4 linux/amd64

Does this issue reproduce with the latest release?

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

go env Output
$ go env
GO111MODULE="auto"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/telesys/.cache/go-build"
GOENV="/home/telesys/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/telesys/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/telesys/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.19.4"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/telesys/USR/HARPAL_M7SEPP_22_6_2_B2_P5_HF1_RC1/m7usp/m7sepp/go.mod"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build922737045=/tmp/go-build -gno-record-gcc-switches"

What did you do?

What did you expect to see?

Http2 requests, with timeout value 5 sec should not be timed out (i.e. response should be received within 5 sec) on introducing a delay of 100ms (or even more, upto around 4 sec) on local VM or in network.

What did you see instead?

Http2 requests (with response wait timer value 5 sec ) are timed out on introducing a delay of 100ms (on local VM).

Even, below settings are not working as expected:
http.Transport -> WriteBufferSize and ReadBufferSize

@Harpal-7
Copy link
Author

Detailed explanation of the issue:

HTTP2 response delayed more than 5 sec by introducing a network delay of just 100 ms

I am writing a high performance http2 client and server applications.
My programs (client and server) handles 3500 http2 requests per sec (with a lot of application logic).
The problem I am facing is, when I introduce an IP delay of 100 ms on the client VM (machine), the most of the requests are timed out, despite the timeout wait at client side is 5 sec.
I am setting the time out value to 5 sec using:
http.Client {
Timeout: timeout,
}

I have observed that client's VM is not able to transmit the packet in time to network. Only 100 ms delay was introduced, but transmitting out the http2 request is taking way too much of time (>5 sec).

Delay was introduced using below command:
tc qdisc add dev eth1 root netem delay 100ms

I observed the goroutines, here is the summary where most of time time went:

  • http2.(*clientStream).writeRequest : occurred around 36% times
  • http.(*Client).Do -> http2.(*ClientConn).RoundTrip : occurred around 31% times
  • http2/h2c.(*rwConn).Read -> poll.(*FD).Read -> poll.runtime_pollWait : occurred around 15% times
    [Detailed back traces are provided at the end]

I also tried to increase the outgoing buffer as below (at client side):
httpTransport := &http.Transport {
WriteBufferSize: 83000000,
ReadBufferSize: 83000000,
}
http2Transport, err := http2.ConfigureTransports(httpTransport)
if err != nil {
return nil, fmt.Errorf("Failed to ConfigureTransports, %v", err)
}

http2Transport.AllowHTTP = true // So http2.Transport doesn't complain the URL scheme isn't 'https'
http2Transport.TLSClientConfig = tlsCfg
http2Transport.DialTLS = dialTls

conn = &Client{
Client: &http.Client{
Transport: http2Transport,
Timeout: timeout,
},
}

But, with this change, the connection are not coming up, giving below error:
http2: no cached connection was available

goroutine 10374884 [select]:
golang.org/x/net/http2.(*clientStream).writeRequest(0xc01f47de00, 0xc02805fa00)
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/transport.go:1340 +0x9c7
golang.org/x/net/http2.(*clientStream).doRequest(0x0?, 0x0?)
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/transport.go:1202 +0x1e
created by golang.org/x/net/http2.(*ClientConn).RoundTrip
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/transport.go:1131 +0x30a

goroutine 10379533 [select]:
golang.org/x/net/http2.(*ClientConn).RoundTrip(0xc011543080, 0xc032556a00)
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/transport.go:1172 +0x451
golang.org/x/net/http2.(*Transport).RoundTripOpt(0xc000ea5d80, 0xc032556a00, {0x80?})
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/transport.go:499 +0x1b7
golang.org/x/net/http2.(*Transport).RoundTrip(0xc032556a00?, 0xdffea0?)
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/transport.go:460 +0x1b
net/http.send(0xc032556800, {0xdffea0, 0xc000ea5d80}, {0xc2d940?, 0x4d4301?, 0x13e6b80?})
/opt/go/src/net/http/client.go:251 +0x5f7
net/http.(*Client).send(0xc0008f1a10, 0xc032556800, {0xc00d146ff0?, 0x20300d?, 0x13e6b80?})
/opt/go/src/net/http/client.go:175 +0x9b
net/http.(*Client).do(0xc0008f1a10, 0xc032556800)
/opt/go/src/net/http/client.go:715 +0x8fc
net/http.(*Client).Do(...)
/opt/go/src/net/http/client.go:581

goroutine 28 [IO wait]:
internal/poll.runtime_pollWait(0x7f071881fd48, 0x72)
/opt/go/src/runtime/netpoll.go:305 +0x89
internal/poll.(*pollDesc).wait(0xc0003fc300?, 0xc000392000?, 0x0)
/opt/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
/opt/go/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0003fc300, {0xc000392000, 0x1000, 0x1000})
/opt/go/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0003fc300, {0xc000392000?, 0x100000000000000?, 0x4?})
/opt/go/src/net/fd_posix.go:55 +0x29
net.(*conn).Read(0xc0003b2010, {0xc000392000?, 0xc00002e588?, 0x15?})
/opt/go/src/net/net.go:183 +0x45
net/http.(*connReader).Read(0xc0002991d0, {0xc000392000, 0x1000, 0x1000})
/opt/go/src/net/http/server.go:786 +0x171
bufio.(*Reader).Read(0xc00007c540, {0xc0002da580, 0x9, 0x446407?})
/opt/go/src/bufio/bufio.go:237 +0x1bb
io.(*multiReader).Read(0xc0001dc150, {0xc0002da580, 0x9, 0x9})
/opt/go/src/io/multi.go:26 +0x9b
golang.org/x/net/http2/h2c.(*rwConn).Read(0x456794?, {0xc0002da580?, 0x2?, 0xc02ecf6c34?})
/home/telesys/go/pkg/mod/golang.org/x/net@v0.0.0-20220225172249-27dd8689420f/http2/h2c/h2c.go:293 +0x27

@seankhliao
Copy link
Member

it seems more likely you misconfigured tc?
see https://stackoverflow.com/questions/18792347/what-does-option-limit-in-tc-netem-mean-and-do

@seankhliao seankhliao added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jul 24, 2023
@seankhliao seankhliao changed the title affected/package: net/http, golang.org/x/net/http2 net/http, x/net/http2 Jul 24, 2023
@seankhliao seankhliao changed the title net/http, x/net/http2 net/http, x/net/http2: small delays trigger timeout Jul 24, 2023
@Harpal-7
Copy link
Author

it seems more likely you misconfigured tc? see https://stackoverflow.com/questions/18792347/what-does-option-limit-in-tc-netem-mean-and-do

Thank you very much, it was really 'limit' option of 'tc' command, without which messages were clogged. I tried with 'limit' option and it worked as expected.
Can you please help me on how to set WriteBufferSize and ReadBufferSize for http2? I tried but but giving this error - 'http2: no cached connection was available' (as described in my query).
Thank you in advance.

@seankhliao seankhliao added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Sep 10, 2023
@gopherbot
Copy link

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

@gopherbot gopherbot closed this as not planned Won't fix, can't repro, duplicate, stale Oct 10, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Development

No branches or pull requests

3 participants