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

ahmed-anas · 2021-09-28T07:03:36Z

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

The text was updated successfully, but these errors were encountered:

mknyszek · 2021-10-04T16:42:40Z

CC @neild

federicobenitezrk · 2021-10-11T12:00:44Z

CC @neild

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

mknyszek added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Performance labels Oct 4, 2021

mknyszek changed the title ~~Go HTTP 2 Client - too many sockets created at high throughput~~ x/net/http2: too many sockets created at high throughput Oct 4, 2021

mknyszek added this to the Unreleased milestone Oct 4, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

ahmed-anas commented Sep 28, 2021 •

edited

mknyszek commented Oct 4, 2021

federicobenitezrk commented Oct 11, 2021

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

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

Comments

ahmed-anas commented Sep 28, 2021 • edited

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

Does this issue reproduce with the latest release?

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

What did you do?

client.go

server.go

What did you expect to see?

What did you see instead?

Go routine dump of client

mknyszek commented Oct 4, 2021

federicobenitezrk commented Oct 11, 2021

ahmed-anas commented Sep 28, 2021 •

edited

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

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