x/net/http2: too many sockets created at high throughput

[ahmed-anas]

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

$ go version go1.16.6 windows/amd64 

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

go env Output

$ 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

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

client.go Output

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()

}

server.go

server.go Output

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))
}

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

go routine sample dump Output

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

[mknyszek]

CC @neild

[federicobenitezrk]

CC @neild

Is there an ETA in when this issue will be investigated?