Repository: go
Issue: x/net/http2: too many sockets created at high throughput 
Labels: Performance,NeedsInvestigation

<!--
Please answer these questions before submitting your issue. Thanks!
For questions please use one of our forums: https://github.com/golang/go/wiki/Questions
-->

### What version of Go are you using (`go version`)?

<pre>
$ go version go1.16.6 windows/amd64 

</pre>

### Does this issue reproduce with the latest release?
yes


### What operating system and processor architecture are you using (`go env`)?
Note: the code is built using ` $Env:GOOS = "linux"; $Env:GOARCH = "arm64"` and tested on a c4x.18xlarge aws ec2 instance
<details><summary><code>go env</code> Output</summary><br><pre>
$ go env
set GO111MODULE=
set GOARCH=arm64
set GOBIN=
set GOCACHE=C:\Users\ahmed\AppData\Local\go-build
set GOENV=C:\Users\ahmed\AppData\Roaming\go\env
set GOEXE=
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=C:\Users\ahmed\go\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=linux
set GOPATH=C:\Users\ahmed\go
set GOPRIVATE=
set GOPROXY=https://proxy.golang.org,direct
set GOROOT=C:\Program Files\Go
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Program Files\Go\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=go1.16.6
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=0
set GOMOD=D:\work\crossover\code\load-test-golang-http\go.mod
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-fPIC -fmessage-length=0 -fdebug-prefix-map=C:\Users\ahmed\AppData\Local\Temp\go-build3860388835=/tmp/go-build -gno-record-gcc-switches
</pre></details>

### What did you do?

Ran an http2 stress-test, client and server on different machines but same VPC. testing with traffic gradually increasing - going up-to 20K requests/second (although issue occured before that limit)

In a separate shell, ran `lsof -p <pid> | wc -l` to monitor the used sockets

This was done in 2 situations
 - server behind an aws ALB (limits 128 concurrent requests in a single connection and sends GO AWAY after 10K requests) 
 - server being hit directly via IP (issue is much less prominent here)

#### client.go
<details><summary><code>client.go</code> Output</summary><br>
<pre>
package main

import (
	"crypto/tls"
	"flag"
	"io/ioutil"
	"log"
	"net/http"
	"strings"
	"sync/atomic"
	"time"
)

func main() {
	endpoint := flag.String("endpoint", "https://10.116.192.87:8090/hello", "the endpoint to request on")
	flag.Parse()
	httpClient := &http.Client{Transport: &http.Transport{
		TLSClientConfig:     &tls.Config{InsecureSkipVerify: true},
		IdleConnTimeout:     0,
		MaxIdleConnsPerHost: 1000,
		//MaxConnsPerHost:     100,
		ForceAttemptHTTP2: true,

	}}

	totalDuration := uint64(0)
	totalRequests := uint64(0)

	go func() {
		lastCount := uint64(0)
		for {
			time.Sleep(5 * time.Second)
			count := atomic.LoadUint64(&totalDuration)
			if count <= 0 {
				println("---- no requests so far ----")
				continue
			}
			currentRequests := atomic.LoadUint64(&totalRequests)
			avgResponseTime := count / currentRequests
			log.Println("----------------------------------")
			log.Printf("average response time: %dms", avgResponseTime/1000000)
			log.Printf("total requests: %d", currentRequests)
			log.Printf("new requests: %d", currentRequests-lastCount)
			log.Println("----------------------------------")

			lastCount = currentRequests
		}
	}()

	requestsThisSecond := 0
	remainingRequests := 0
	requestIncreasePerSecond := 500
	maxRequestsPerSecond := 50000
	reachedMaxSpeed := false
	sleepTime := time.Duration(0)

	for {
		if remainingRequests <= 0 && !reachedMaxSpeed {
			requestsThisSecond = requestsThisSecond + requestIncreasePerSecond
			if requestsThisSecond >= maxRequestsPerSecond {
				requestsThisSecond = maxRequestsPerSecond
				reachedMaxSpeed = true
				log.Printf("--->>>Reached Max Throuput of %d requests per second<<<---", maxRequestsPerSecond)
			}

			microSecondSleep := time.Duration(float64(1000000 / requestsThisSecond))
			sleepTime = time.Microsecond * microSecondSleep
			remainingRequests = requestsThisSecond
		}

		go sendRequest(httpClient, *endpoint, &totalDuration)
		atomic.AddUint64(&totalRequests, 1)

		if !reachedMaxSpeed {
			remainingRequests = remainingRequests - 1
		}

		time.Sleep(sleepTime)
	}
}

func sendRequest(httpClient *http.Client, endpoint string, totalDuration *uint64) {

	body := "{ \"a\": \"bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb\"}"

	httpReq, err := http.NewRequest("POST", endpoint, strings.NewReader(body))

	if err != nil {
		log.Println("error while sending request")
		log.Println(err)
		return
	}

	httpReq.Header.Add("Authorization", "Bearer XXXX")
	httpReq.Header.Add("Content-Type", "application/json")
	httpReq.Header.Add("Accept", "application/json")

	startTime := time.Now().UnixNano()
	httpRes, err := httpClient.Do(httpReq)
	duration := time.Now().UnixNano() - startTime
	atomic.AddUint64(totalDuration, uint64(duration))

	if err != nil {
		log.Println("error while receiving response")
		log.Println(err)
		return
	}

	if httpRes.StatusCode < 200 || httpRes.StatusCode > 300 {
		log.Println("status code was not 2XX")
	}

	httpResBodyByte, err := ioutil.ReadAll(httpRes.Body)

	httpResBody := string(httpResBodyByte)

	if err != nil {
		log.Println("error reading body")
		log.Println(err)
	}

	expectedResponse := "{\"hey\": \"there\"}"
	if httpResBody != expectedResponse {
		log.Printf("expected response to be '%s' but was '%s'", expectedResponse, httpResBody)
	}

	//log.Printf("received %s", httpResBody)

	httpRes.Body.Close()
}

</pre>
</details>

#### server.go

<details><summary><code>server.go</code> Output</summary><br>

```
package main

import (
	"flag"
	"log"
	"net/http"
	"time"
)

func main() {
	addr := flag.String("addr", ":8090", "The address of diameter server - hostname:port")
	flag.Parse()

	http.HandleFunc("/", func(rw http.ResponseWriter, r *http.Request) {
		rw.Header().Set("Content-Type", "application/json")
		response := "{\"hey\": \"there\"}"
		time.Sleep(time.Millisecond * 35)
		rw.Write([]byte(response))
	})

	certFile := "cert.pem"
	keyFile := "key.pem"

	log.Printf("listening on %s", *addr)
	log.Fatal(http.ListenAndServeTLS(*addr, certFile, keyFile, nil))
}

```
</details>

### What did you expect to see?
 - The number shown by the ``lsof -p <pid> | wc -l`` would gradually increase. 
 - the latency would gradually increase 
 - would not see a whole stash of errors 


### What did you see instead?
 - The number shown by the ``lsof -p <pid> | wc -l`` jumped . 
 - the latency jumped
 - saw a bunch of errors
 
 
### Go routine dump of client
the overwhelming majority of goroutines are stuck at `h2_bundle.go:763`
 
<details><summary><code>go routine sample dump</code> Output</summary><br><pre>


goroutine 6657107 [semacquire]:
sync.runtime_SemacquireMutex(0x400018edbc, 0x1c3400, 0x1)
        C:/Program Files/Go/src/runtime/sema.go:71 +0x40
sync.(*Mutex).lockSlow(0x400018edb8)
        C:/Program Files/Go/src/sync/mutex.go:138 +0xf4
sync.(*Mutex).Lock(...)
        C:/Program Files/Go/src/sync/mutex.go:81
net/http.(*http2clientConnPool).getClientConn(0x400018edb0, 0x4022a6c400, 0x405ea16510, 0x12, 0x40533a0200, 0x4b8043a146a2, 0x407eec6910, 0x40533a0240)
        C:/Program Files/Go/src/net/http/h2_bundle.go:763 +0x320
net/http.http2noDialClientConnPool.GetClientConn(0x400018edb0, 0x4022a6c400, 0x405ea16510, 0x12, 0x2, 0x1, 0x1)
        C:/Program Files/Go/src/net/http/h2_bundle.go:953 +0x44
net/http.(*http2Transport).RoundTripOpt(0x40001f0000, 0x4022a6c400, 0x22cc00, 0x400018ede0, 0x27a804, 0x5)
        C:/Program Files/Go/src/net/http/h2_bundle.go:6974 +0xf4
net/http.(*http2Transport).RoundTrip(...)
        C:/Program Files/Go/src/net/http/h2_bundle.go:6942
net/http.http2noDialH2RoundTripper.RoundTrip(0x40001f0000, 0x40017f0700, 0x2c7cf8, 0x40001f0000, 0x0)
        C:/Program Files/Go/src/net/http/h2_bundle.go:9197 +0x34
net/http.(*Transport).roundTrip(0x40001d6280, 0x400ea90d00, 0x404b8d3a00, 0x59a01, 0x404b8d3b08)
        C:/Program Files/Go/src/net/http/transport.go:537 +0xa44
net/http.(*Transport).RoundTrip(0x40001d6280, 0x400ea90d00, 0x40001d6280, 0x0, 0x0)
        C:/Program Files/Go/src/net/http/roundtrip.go:17 +0x30
net/http.send(0x400ea90d00, 0x2c7498, 0x40001d6280, 0x0, 0x0, 0x0, 0x0, 0x40583991f0, 0x4006082ea0, 0x1)
        C:/Program Files/Go/src/net/http/client.go:251 +0x348
net/http.(*Client).send(0x400018ec60, 0x400ea90d00, 0x0, 0x0, 0x0, 0x40583991f0, 0x0, 0x1, 0x404b8d3d38)
        C:/Program Files/Go/src/net/http/client.go:175 +0xc8
net/http.(*Client).do(0x400018ec60, 0x400ea90d00, 0x0, 0x0, 0x0)
        C:/Program Files/Go/src/net/http/client.go:717 +0x33c
net/http.(*Client).Do(...)
        C:/Program Files/Go/src/net/http/client.go:585
main.sendRequest(0x400018ec60, 0x27a804, 0x20, 0x40001a8288)
        D:/work/crossover/code/load-test-golang-http/client.go:99 +0x334
created by main.main
        D:/work/crossover/code/load-test-golang-http/client.go:71 +0x270
</pre></details>