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

[erin-noe-payne]

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!

[bradfitz]

This is almost certainly #16512

I think vegeta is starved for flow control tokens.

/cc @tombergan

[tombergan]

Also see #17985

[tombergan]

@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]

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]

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

[yonderblue]

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]

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

[Scratch-net]

Maybe it's somehow related to #18309

[gopherbot]

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

[gopherbot]

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

[tombergan]

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

[erin-noe-payne]

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

[bradfitz]

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

[bradfitz]

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