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

[Harpal-7]

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]

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]

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

[Harpal-7]

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.

[gopherbot]

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.)