net/http: HTTP2 pushing is suprisingly slow

mitar commented 2 years ago

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

$ go version
go version go1.17.7 linux/amd64

Does this issue reproduce with the latest release?

Yes.

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/mitar/.cache/go-build"
GOENV="/home/mitar/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/mitar/.go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/mitar/.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.17.7"
GCCGO="/usr/bin/gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/dev/null"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build680865618=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I am trying to push multiple requests using HTTP2.

What did you expect to see?

From reading pusher.Push documentation, my expectation was that pushing negligibly impacts time the main request is served, as all pushing happens in separate goroutines.

What did you see instead?

I am observing that this is not the case. I made a simple test and pushing 100 requests with 10 KB large responses takes 8 ms on my local machine, pushing 100 requests with 1 MB large responses takes 35 ms. So this is just additional time added to the main request handling to call pusher.Push in a loop. Not how long it takes for the pushed responses themselves to be delivered. This is a surprising amount to me.

From looking at the code, I think the issue is that pusher.Push waits until it can send a startPushRequest message to serveMsgCh and with many push requests this can block for non-trivial amount of time.

I made a small example here. See README for instructions how to run it.

seankhliao commented 2 years ago

cc @neild

mitar commented 2 years ago

It seems it might not be the serveMsgCh. I increased queue size to 800 to experiment and it was still slow. So being able to push into serveMsgCh quickly might not be the issue. So probably it is being blocked on processing the message and waiting on msg.done.

mitar commented 2 years ago

cc @dunglas, Not sure if you experienced this. I was trying to do something similar to Vulcain, and push embedded objects using HTTP push instead of embedding them into the main object, but observed increased latency of processing the main request is somewhat killing the point.

golang / go