x/net/http2: Server is slow under load (flow control?) #18404

erin-noe-payne · 2016-12-21T18:59:11Z

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

go version go1.7.4 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/erin.noe-payne/local/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"

What did you do?

Start an http server.
Put it under some load: 25 req / s for 10s, each posting a 5mb text file
Compare the results for https/1.1 to http/2

The server code:

package main

import (
	"io/ioutil"
	"log"
	"net/http"
)

type handler struct{}

func (*handler) ServeHTTP(res http.ResponseWriter, req *http.Request) {
	ioutil.ReadAll(req.Body)
	req.Body.Close()
}

func main() {
	server := &http.Server{
		Addr:    ":3000",
		Handler: &handler{},
		// Uncomment to disable http/2
		// TLSNextProto: make(map[string]func(*http.Server, *tls.Conn, http.Handler)),
	}

	log.Fatal(server.ListenAndServeTLS("tls/server.crt", "tls/server.key"))
}

Create a data file for testing:
$ mkfile -n 5m 5mb.txt

Using the vegeta load test client:
$ echo PUT https://localhost:3000/ | vegeta attack -insecure -duration=10s -rate=25 -body=5mb.txt | vegeta report

Run the same test against the server running in http/1.1 and http/2 mode.

What did you expect to see?

I would expect the performance (average latency / throughput) of an http/2 server to be similar or better than http/1.1.

What did you see instead?

HTTP/2 results:

Making 25 req/s over 10s
Requests      [total, rate]            250, 25.10
Duration      [total, attack, wait]    42.305466622s, 9.959999799s, 32.345466823s
Latencies     [mean, 50, 95, 99, max]  31.880917546s, 33.618733832s, 37.184070581s, 37.822213047s, 38.701059773s
Bytes In      [total, mean]            0, 0.00
Bytes Out     [total, mean]            1310720000, 5242880.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:250

HTTP/1.1 results:

Making 25 req/s over 10s
Requests      [total, rate]            250, 25.10
Duration      [total, attack, wait]    10.044000447s, 9.959999916s, 84.000531ms
Latencies     [mean, 50, 95, 99, max]  105.904846ms, 81.203795ms, 233.098998ms, 315.526192ms, 504.860265ms
Bytes In      [total, mean]            0, 0.00
Bytes Out     [total, mean]            1310720000, 5242880.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:250

Further info:

If I reduce load to very low levels (say 1 req/s) HTTP 2 and 1.1 are comparable.
If I do not read the bytes off of the request - ioutil.ReadAll(req.Body) - then requests are processed quickly (fairly obvious)
The memory allocated for the process goes through the roof (~1.5GB) when http/2 is enabled. I am guessing this is because the latency is so high that many requests are being kept open in parallel, and all of their bodies are being held in memory.
I ran a trace on the server while running these tests. I don't have a ton of experience using the tracing / pprof tools, but one thing that stands out is the huge number of goroutines spun up:
The other is the huge amount of time blocking on a sync.Wait:

Conclusion

Basically, HTTP/2 is merged into core and enabled by default on TLS servers. This leads me to expect that an HTTP/2 server should perform similarly or better than an HTTP/1.1 server under most conditions. I wish to build performant REST APIs that can sustain reasonable throughput, and HTTP/2 offers a number of features that I had assumed would improve performance.

I'm not clear if this is a bad assumption, I am misusing the APIs somehow, or this reflects an issue with the implementation. Any support, information, or recommendations would be greatly appreciated. Thanks!

The text was updated successfully, but these errors were encountered:

bradfitz · 2016-12-21T19:25:41Z

This is almost certainly #16512

I think vegeta is starved for flow control tokens.

/cc @tombergan

tombergan · 2016-12-21T19:48:54Z

Also see #17985

tombergan · 2016-12-21T22:54:34Z

@bradfitz, I think this is more than #16512. Why are there 2 conn.serve goroutines but 165212 conn.writeFrameAsync goroutines? There should be at most one writeFrameAsync goroutine per serve goroutine. There is either a bug that triggers multiple concurrent frame writes, or a goroutine leak that doesn't cleanup writeFrameAsync goroutines. The latter seems likely. Probably this should wait for "wroteFrameCh<-" or doneServing?
https://github.com/golang/net/blob/45e771701b814666a7eb299e6c7a57d0b1799e91/http2/server.go#L640

erin-noe-payne · 2016-12-28T18:20:05Z

Hey guys, thanks for the quick response. This discussion leads to some follow-up questions:

Is this the flow control window size at the connection level - the connection is effectively throttling the throughput?
Is this the flow control window size at the stream level - the small buffer size is causing thrashing on reads and contention between the various goroutines? Does that even make sense?
In either case, what options do I have to fix it? The only configuration I see exposed is the http/2 server's MaxReadFrameSize. Will that affect both connection and stream window sizes?

bradfitz · 2016-12-28T18:30:51Z

@autoric, yup, those are the questions this bug is about investigating. We'll probably need better (or automatic) defaults, and more knobs.

yonderblue · 2017-01-05T22:48:33Z

I'm always a fan of the no knob solution, but if there could be knobs only in the http2 pkg offered earlier than the auto solution it would be great for us.

gopherbot · 2017-01-11T23:35:54Z

CL https://golang.org/cl/35118 mentions this issue.

Scratch-net · 2017-02-04T20:48:11Z

Maybe it's somehow related to #18309

gopherbot · 2017-02-18T20:46:12Z

CL https://golang.org/cl/37226 mentions this issue.

Upload performance is poor when BDP is higher than the flow-control window. Previously, the server's receive window was fixed at 64KB, which resulted in very poor performance for high-BDP links. The receive window now defaults to 1MB and is configurable. The per-connection and per-stream windows are configurable separately (both default to 1MB as suggested in golang/go#16512). Previously, the server created a "fixedBuffer" for each request body. This is no longer a good idea because a fixedBuffer has fixed size, which means individual streams cannot use varying amounts of the available connection window. To overcome this limitation, I replaced fixedBuffer with "dataBuffer", which grows and shrinks based on current usage. The worst-case fragmentation of dataBuffer is 32KB wasted memory per stream, but I expect that worst-case will be rare. A slightly modified version of adg@'s grpcbench program shows a dramatic improvement when increasing from a 64KB window to a 1MB window, especially at higher latencies (i.e., higher BDPs). Network latency was simulated with netem, e.g., `tc qdisc add dev lo root netem delay 16ms`. Duration Latency Proto H2 Window 11ms±4.05ms 0s HTTP/1.1 - 17ms±1.95ms 0s HTTP/2.0 65535 8ms±1.75ms 0s HTTP/2.0 1048576 10ms±1.49ms 1ms HTTP/1.1 - 47ms±2.91ms 1ms HTTP/2.0 65535 10ms±1.77ms 1ms HTTP/2.0 1048576 15ms±1.69ms 2ms HTTP/1.1 - 88ms±11.29ms 2ms HTTP/2.0 65535 15ms±1.18ms 2ms HTTP/2.0 1048576 23ms±1.42ms 4ms HTTP/1.1 - 152ms±0.77ms 4ms HTTP/2.0 65535 23ms±0.94ms 4ms HTTP/2.0 1048576 40ms±1.54ms 8ms HTTP/1.1 - 288ms±1.67ms 8ms HTTP/2.0 65535 39ms±1.29ms 8ms HTTP/2.0 1048576 72ms±1.13ms 16ms HTTP/1.1 - 559ms±0.68ms 16ms HTTP/2.0 65535 71ms±1.12ms 16ms HTTP/2.0 1048576 136ms±1.15ms 32ms HTTP/1.1 - 1104ms±1.62ms 32ms HTTP/2.0 65535 135ms±0.96ms 32ms HTTP/2.0 1048576 264ms±0.95ms 64ms HTTP/1.1 - 2191ms±2.08ms 64ms HTTP/2.0 65535 263ms±1.57ms 64ms HTTP/2.0 1048576 Fixes golang/go#16512 Updates golang/go#17985 Updates golang/go#18404 Change-Id: Ied385aa94588337e98dad9475cf2ece2f39ba346 Reviewed-on: https://go-review.googlesource.com/37226 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org>

gopherbot · 2017-02-27T19:15:49Z

CL https://golang.org/cl/37500 mentions this issue.

tombergan · 2017-02-27T19:21:17Z

@autoric, do the above two changes fix the problem? I'm a bit concerned about the number of goroutines (see prior comment) but the flow control problem should be fixed.

Updates http2 to x/net/http2 git rev 906cda9 for: http2: add configurable knobs for the server's receive window https://golang.org/cl/37226 http2/hpack: speedup Encoder.searchTable https://golang.org/cl/37406 http2: Add opt-in option to Framer to allow DataFrame struct reuse https://golang.org/cl/34812 http2: replace fixedBuffer with dataBuffer https://golang.org/cl/37400 http2/hpack: remove hpack's constant time string comparison https://golang.org/cl/37394 Updates #16512 Updates #18404 Change-Id: I1ad7c95c404ead4ced7f85af061cf811b299a288 Reviewed-on: https://go-review.googlesource.com/37500 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org>

erin-noe-payne · 2017-02-28T00:40:35Z

@tombergan Thanks for the update! I will run tests in the next couple days and get back to you.

bradfitz · 2017-05-23T23:51:28Z

@autoric, any updates? Please try Go master before it becomes Go 1.9beta1 soonish here.

bradfitz · 2017-06-07T21:36:40Z

Timeout. I assume this was fixed. Comment if not.

Upload performance is poor when BDP is higher than the flow-control window. Previously, the server's receive window was fixed at 64KB, which resulted in very poor performance for high-BDP links. The receive window now defaults to 1MB and is configurable. The per-connection and per-stream windows are configurable separately (both default to 1MB as suggested in golang/go#16512). Previously, the server created a "fixedBuffer" for each request body. This is no longer a good idea because a fixedBuffer has fixed size, which means individual streams cannot use varying amounts of the available connection window. To overcome this limitation, I replaced fixedBuffer with "dataBuffer", which grows and shrinks based on current usage. The worst-case fragmentation of dataBuffer is 32KB wasted memory per stream, but I expect that worst-case will be rare. A slightly modified version of adg@'s grpcbench program shows a dramatic improvement when increasing from a 64KB window to a 1MB window, especially at higher latencies (i.e., higher BDPs). Network latency was simulated with netem, e.g., `tc qdisc add dev lo root netem delay 16ms`. Duration Latency Proto H2 Window 11ms±4.05ms 0s HTTP/1.1 - 17ms±1.95ms 0s HTTP/2.0 65535 8ms±1.75ms 0s HTTP/2.0 1048576 10ms±1.49ms 1ms HTTP/1.1 - 47ms±2.91ms 1ms HTTP/2.0 65535 10ms±1.77ms 1ms HTTP/2.0 1048576 15ms±1.69ms 2ms HTTP/1.1 - 88ms±11.29ms 2ms HTTP/2.0 65535 15ms±1.18ms 2ms HTTP/2.0 1048576 23ms±1.42ms 4ms HTTP/1.1 - 152ms±0.77ms 4ms HTTP/2.0 65535 23ms±0.94ms 4ms HTTP/2.0 1048576 40ms±1.54ms 8ms HTTP/1.1 - 288ms±1.67ms 8ms HTTP/2.0 65535 39ms±1.29ms 8ms HTTP/2.0 1048576 72ms±1.13ms 16ms HTTP/1.1 - 559ms±0.68ms 16ms HTTP/2.0 65535 71ms±1.12ms 16ms HTTP/2.0 1048576 136ms±1.15ms 32ms HTTP/1.1 - 1104ms±1.62ms 32ms HTTP/2.0 65535 135ms±0.96ms 32ms HTTP/2.0 1048576 264ms±0.95ms 64ms HTTP/1.1 - 2191ms±2.08ms 64ms HTTP/2.0 65535 263ms±1.57ms 64ms HTTP/2.0 1048576 Fixes golang/go#16512 Updates golang/go#17985 Updates golang/go#18404 Change-Id: Ied385aa94588337e98dad9475cf2ece2f39ba346 Reviewed-on: https://go-review.googlesource.com/37226 Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org>

bradfitz added this to the Go1.9 milestone Dec 21, 2016

bradfitz changed the title ~~HTTP/2 is slow under load~~ x/net/http2: Server is slow under load (flow control?) Dec 21, 2016

bradfitz added the WaitingForInfo label May 23, 2017

bradfitz modified the milestones: Go1.9Maybe, Go1.9 May 23, 2017

bradfitz closed this as completed Jun 7, 2017

golang locked and limited conversation to collaborators Jun 7, 2018

gopherbot added the FrozenDueToAge label Jun 7, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

x/net/http2: Server is slow under load (flow control?) #18404

x/net/http2: Server is slow under load (flow control?) #18404

erin-noe-payne commented Dec 21, 2016 •

edited

Loading

bradfitz commented Dec 21, 2016

tombergan commented Dec 21, 2016

tombergan commented Dec 21, 2016

erin-noe-payne commented Dec 28, 2016

bradfitz commented Dec 28, 2016

yonderblue commented Jan 5, 2017

gopherbot commented Jan 11, 2017

Scratch-net commented Feb 4, 2017

gopherbot commented Feb 18, 2017

gopherbot commented Feb 27, 2017

tombergan commented Feb 27, 2017

erin-noe-payne commented Feb 28, 2017

bradfitz commented May 23, 2017

bradfitz commented Jun 7, 2017

x/net/http2: Server is slow under load (flow control?) #18404

x/net/http2: Server is slow under load (flow control?) #18404

Comments

erin-noe-payne commented Dec 21, 2016 • edited Loading

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

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

What did you do?

What did you expect to see?

What did you see instead?

Further info:

Conclusion

bradfitz commented Dec 21, 2016

tombergan commented Dec 21, 2016

tombergan commented Dec 21, 2016

erin-noe-payne commented Dec 28, 2016

bradfitz commented Dec 28, 2016

yonderblue commented Jan 5, 2017

gopherbot commented Jan 11, 2017

Scratch-net commented Feb 4, 2017

gopherbot commented Feb 18, 2017

gopherbot commented Feb 27, 2017

tombergan commented Feb 27, 2017

erin-noe-payne commented Feb 28, 2017

bradfitz commented May 23, 2017

bradfitz commented Jun 7, 2017

erin-noe-payne commented Dec 21, 2016 •

edited

Loading

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

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