net/http, crypto/tls: first HTTP request is consistently slower during TLS handshake in Go 1.17, but not 1.18

[janivanecky]

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

$ go version
go version go1.17.5 darwin/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=""
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.5"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/0h/wc_q919d4_9_f0wj1p4v4h840000gn/T/go-build4221745526=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I'm seeing the first http request using net/http package and Client to be consistently 100-200ms slower than the consecutive ones. This happens both when sending requests to one or multiple servers. The code to reproduce the issue:

package main

import (
	"crypto/tls"
	"fmt"
	"net/http"
	"net/http/httptrace"
	"time"
)

func main() {
	request := func (client *http.Client, url string) {
		t := time.Now()
		fmt.Println("")
		clientTrace := &httptrace.ClientTrace{
			GetConn:      func(hostPort string) { s := time.Now(); fmt.Println(s.Sub(t), "starting to create conn ", hostPort); t = s },
			DNSStart:     func(info httptrace.DNSStartInfo) { s := time.Now(); fmt.Println(s.Sub(t), "starting to look up dns", info); t = s },
			DNSDone:      func(info httptrace.DNSDoneInfo) { s := time.Now(); fmt.Println(s.Sub(t), "done looking up dns", info); t = s },
			ConnectStart: func(network, addr string) { s := time.Now(); fmt.Println(s.Sub(t), "starting tcp connection", network, addr); t = s },
			ConnectDone:  func(network, addr string, err error) { s := time.Now(); fmt.Println(s.Sub(t), "tcp connection created", network, addr, err) ; t = s},
			GotConn:      func(info httptrace.GotConnInfo) { s := time.Now(); fmt.Println(s.Sub(t), "connection established", info.Reused); t = s },
			GotFirstResponseByte: func() { s := time.Now(); fmt.Println(s.Sub(t), "got first byte"); t = s },
			TLSHandshakeStart: func() { s := time.Now(); fmt.Println(s.Sub(t), "handshake start"); t = s },
			TLSHandshakeDone: func(tt tls.ConnectionState, e error) {s := time.Now(); fmt.Println(s.Sub(t), "handshake end"); t = s},
		}
		
		req, _ := http.NewRequest("GET", url, nil)
		req.Close = true
		clientTraceCtx := httptrace.WithClientTrace(req.Context(), clientTrace)
		req = req.WithContext(clientTraceCtx)
		response, _ := client.Do(req)
		response.Body.Close()
	}

	client := &http.Client{}
	request(client, "https://news.ycombinator.com")
	client = &http.Client{}
	request(client, "https://news.ycombinator.com")
	client = &http.Client{}
	request(client, "https://news.ycombinator.com")
}

What did you expect to see?

Roughly the same timings for all the requests.

What did you see instead?

145.166µs starting to create conn  news.ycombinator.com:443
276.459µs starting to look up dns {news.ycombinator.com}
58.451916ms done looking up dns {[{209.216.230.240 }] <nil> false}
616.542µs starting tcp connection tcp 209.216.230.240:443
190.6365ms tcp connection created tcp 209.216.230.240:443 <nil>
711.875µs handshake start
517.936208ms handshake end
620.167µs connection established false
194.723083ms got first byte

115.5µs starting to create conn  news.ycombinator.com:443
93.959µs starting to look up dns {news.ycombinator.com}
8.060583ms done looking up dns {[{209.216.230.240 }] <nil> false}
41.167µs starting tcp connection tcp 209.216.230.240:443
179.021541ms tcp connection created tcp 209.216.230.240:443 <nil>
224.875µs handshake start
362.071834ms handshake end
152.291µs connection established false
180.119625ms got first byte

91.333µs starting to create conn  news.ycombinator.com:443
129.208µs starting to look up dns {news.ycombinator.com}
2.597417ms done looking up dns {[{209.216.230.240 }] <nil> false}
74.833µs starting tcp connection tcp 209.216.230.240:443
181.5515ms tcp connection created tcp 209.216.230.240:443 <nil>
151.334µs handshake start
359.525791ms handshake end
157.042µs connection established false
179.980583ms got first byte

The slowdown for the first request happens for every server I tried and it's always only the first request, whether the Client is reused or recreated for every request.

Just to make sure that there's no confusion - I tried this for multiple servers, the first request is always slower. For server X, the average request duration is N if it's the first request and M if it's one of the consecutive requests. Duration M for consecutive requests is roughly the same across multiple runs regardless of whether the first request was to the server X or some other server. The duration M is always 100-200ms lower than N.

The logs I posted seem to indicate that the bulk of the slowdown is coming from TLS handshake. I couldn't find anything in the code that would point to some overhead/initialization happening exclusively for the first request.

I'm not necessarily saying there's a bug - this might be the expected behavior. In that case it would be great to update the documentation, I spend few hours researching this and found no explanation for this behavior.

Thank you for your time!

[dmitshur]

In the test performed, client := &http.Client{} looks suspicious. From https://pkg.go.dev/net/http#Client.Transport:

// Transport specifies the mechanism by which individual
// HTTP requests are made.
// If nil, DefaultTransport is used.
Transport RoundTripper

If all 3 instances of an HTTP client end up reusing the default transport, there may be something cached and reused for future connections.

Maybe this isn't a problem because of req.Close = true line, but still, I'd suggest avoiding reusing the transport to make the test more fair.

This doesn't appear to reproduce consistently for me with Go 1.18 Beta 1 and using my internet. I got a result that looks like:

$ go run . | grep "got first byte"
112.980708ms got first byte
93.152333ms got first byte
84.753375ms got first byte
$ go run . | grep "got first byte"
79.133125ms got first byte
85.475709ms got first byte
82.661083ms got first byte
$ go run . | grep "got first byte"
80.984625ms got first byte
78.987416ms got first byte
91.047583ms got first byte

So, it happened on first program execution, but not second and third.

I would imagine this can happen because of how the internet works: when making a request to a new server for the first time, routers take a bit longer to route packets the first time. For subsequent requests, those "first time" delays aren't incurred. For related discussion, see https://stackoverflow.com/questions/54078692/why-first-network-call-takes-more-time-than-subsequent-ones.

This is to say there may still be room for improvement in certain parts of net/http, but the provided test is too high level to find where the opportunities may be.

[dmitshur]

consistently 100-200ms slower

Can you clarify how you're getting to that number? From your log, it looked like all 3 requests got first byte within 20 ms, not 100-200 ms.

[janivanecky]

I'd suggest avoiding reusing the transport to make the test more fair.

I tried running this with creating each client like this:

client := &http.Client{
	Transport: &http.Transport{
		Proxy: http.ProxyFromEnvironment,
		DialContext: (&net.Dialer{
			Timeout:   30 * time.Second,
			KeepAlive: 30 * time.Second,
		}).DialContext,
		ForceAttemptHTTP2:     true,
		MaxIdleConns:          100,
		IdleConnTimeout:       90 * time.Second,
		TLSHandshakeTimeout:   10 * time.Second,
		ExpectContinueTimeout: 1 * time.Second,
	},
}

and the issue persists.

Can you clarify how you're getting to that number? From your log, it looked like all 3 requests got first byte within 20 ms, not 100-200 ms.

Yes, I was not clear about this in my original post - the line to track is handshake end in the log. The timings are not cumulative.

janivanecky@MacBook-Pro blnk % go run example.go | grep "handshake end"
499.478584ms handshake end
358.794625ms handshake end
358.046667ms handshake end
janivanecky@MacBook-Pro blnk % go run example.go | grep "handshake end"
496.45375ms handshake end
363.463291ms handshake end
356.473209ms handshake end

I would imagine this can happen because of how the internet works: when making a request to a new server for the first time, routers take a bit longer to route packets the first time. For subsequent requests, those "first time" delays aren't incurred. For related discussion, see https://stackoverflow.com/questions/54078692/why-first-network-call-takes-more-time-than-subsequent-ones.

Makes sense, but I'm seeing the same thing when sending requests across different servers:

janivanecky@MacBook-Pro blnk % go run example.go | grep "handshake end"
487.623042ms https://news.ycombinator.com handshake end
33.04375ms https://twitter.com handshake end
janivanecky@MacBook-Pro blnk % go run example.go | grep "handshake end"
131.811708ms https://twitter.com handshake end
360.978583ms https://news.ycombinator.com handshake end

[dmitshur]

Thanks for clarifying.

I'm still not seeing the same difference you're describing on my machine, at least not with Go 1.18 Beta 1:

$ go run . | grep "handshake end"
184.652292ms handshake end
185.861708ms handshake end
232.005459ms handshake end
$ go run . | grep "handshake end"
206.014125ms handshake end
198.452334ms handshake end
171.361875ms handshake end
$ go run . | grep "handshake end"
181.764333ms handshake end
180.761042ms handshake end
176.7205ms handshake end

Edit: But I do see it with Go 1.17.5!

I'll let someone more familiar with net/http and crypto/tls take a look, possibly later on due to #50241.

[janivanecky]

Thank you anyways Dmitri!

I tried running this with Go 1.18 Beta 1 and I don't see the issue either. I think the absolute first request to the server is still the slowest, by a small margin, but the speed up persists across multiple runs.