net/http: Transport.MaxConnsPerHost doesn't work well with HTTP/2

[gaboose]

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

go version go1.11 linux/amd64

Does this issue reproduce with the latest release?

Yes

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

GOHOSTARCH="amd64"
GOHOSTOS="linux"

What did you do?

I ran a program that quickly and concurrently executes 10 http requests to the same url from a single http.Client, also httptraceing TLSHandshakeStart and GotConn events.

package main

import (
	"fmt"
	"net/http"
	"net/http/httptrace"
	"sync"
)

func checkError(err error) {
	if err != nil {
		panic(err)
	}
}

func main() {
	client := &http.Client{}
	req, err := http.NewRequest("GET", "https://golang.org/doc/", nil)
	checkError(err)

	trace := &httptrace.ClientTrace{
		GotConn: func(connInfo httptrace.GotConnInfo) {
			fmt.Printf("Got Conn: %+v\n", connInfo)
		},
		TLSHandshakeStart: func() {
			fmt.Println("TLSHandshakeStart")
		},
	}
	req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))

	wg := sync.WaitGroup{}
	for i := 0; i < 10; i++ {
		wg.Add(1)
		go func() {
			_, err := client.Do(req)
			checkError(err)
			wg.Done()
		}()
	}
	wg.Wait()
}

What did you expect to see?

TLSHandshakeStart being printed as many times as GotConn: {[...] Reused:false [...]} - only once.

What did you see instead?

TLSHandhshakeStart is printed 10 times, but GotConn reports that it reused the connection 9 times out of 10.

This is the full output:

TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
TLSHandshakeStart
Got Conn: {Conn:0xc4202b6000 Reused:false WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc4202b6000 Reused:true WasIdle:false IdleTime:0s}

The large number of TLS handshakes is a big performance hit for us. This doesn't happen if I specify an http2 transport explicitly:

- client := &http.Client{}
+ client := &http.Client{Transport: &http2.Transport{}}

Additionally strace -f -e trace=network -s 10000 ./mytestprogram prints ~10 times less connect syscalls if I specify the http2 transport explicitly.

[bcmills]

CC @bradfitz @rsc

[fraenkel]

@gaboose Set your MaxConnsPerHost. You are using the default which is unlimited.

[gaboose]

@fraenkel That didn't fix it.

- client := &http.Client{}
+ client := &http.Client{Transport: &http.Transport{MaxConnsPerHost: 2}}

gives

TLSHandshakeStart
TLSHandshakeStart
Got Conn: {Conn:0xc00020a380 Reused:false WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
TLSHandshakeStart
TLSHandshakeStart
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
TLSHandshakeStart
TLSHandshakeStart
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
TLSHandshakeStart
TLSHandshakeStart
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
TLSHandshakeStart
TLSHandshakeStart
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}
Got Conn: {Conn:0xc00020a380 Reused:true WasIdle:false IdleTime:0s}

[meirf]

I'm not sure if it's a problem that GotConn is being called a bunch of time since the tracing shows that the connection is being reused. Seems like the bigger problem is that the TLS handshake happens more than once. And @gaboose 's strace comment shows that this isn't a tracing bug.

@gaboose is this right?

[gaboose]

@meirf Yes, I think TLS handshake should happen only once, especially because the connection seems to be successfully reused. I first discovered this by seeing too much of cpu time being spent in crypto/tls.(*Conn).clientHandshake while profiling. That's definitely the problem I want to report here. Sorry for not being clearer.

[bradfitz]

As @fraenkel said, the answer is supposed to be MaxConnsPerHost (which was #13957) but that appeared late-ish in the Go 1.11 cycle and didn't get enough attention from me & other testers: it appears that it doesn't work that well with HTTP/2.

What's happening for HTTP/2 is that before the dial it acquires a token from the semaphore, dials, handshakes, realizes it's HTTP/2, and then immediately releases the token, before adding the connection to the connection pool. The second problem is that connection acquistion code's MaxConnsPerHost path doesn't re-check for idle connections after doing the semaphore wait, which only matters for HTTP/2 (for HTTP/1, it gets idle connections from the t.getIdleConnCh select case).

@meirf, do you want to work on this more?

[meirf]

Yes I’d like to. I clearly have more to learn here.

bradfitz, thanks for investigating. gaboose, thanks for posting.

[meirf]

@fraenkel, any interest in taking this? (I don't have much bandwidth right now.)

[fraenkel]

@meirf Sure, I'll take a crack at it.

[fraenkel]

@bradfitz Do you have a preference on how we manage the http2 connection on the http side? The problem right now is that we attempt a RoundTrip and if that does not exist or fails we dial. No where do we track the pconn.
I can try to treat this pconn as a persistent idle connection, however we cannot decrement the host count until we know the pconn/pconn.conn is closed unless we want to allow for a race and invalidate the MaxConnHosts contract.
The tricky part is knowing when the pconn.conn is closed. Because we pass a tls.Conn to h2, I cannot wrap it. The only way I see around this is to just decrement when we fail trying to reuse the connection from h2. I am just wondering if I am missing something more obvious or easier.