net/http: Slow HTTPS

[gfyrag]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.9.2 linux/amd64

Does this issue reproduce with the latest release?

Not tested.

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/gfyrag/work/gospace"
GORACE=""
GOROOT="/usr/lib/go"
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build524283905=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
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"

What did you do?

package test

import (
	"testing"
	"net/http"
	"net/http/httptest"
	"io"
	"io/ioutil"
)

var (
	data = make([]byte, 1024*1024*100)
	h = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		w.Write(data)
	})
)

func BenchmarkHTTP(b *testing.B) {
	srv := httptest.NewServer(h)
	defer srv.Close()

	b.ResetTimer()
	for i := 0 ; i < b.N ; i++ {
		res, err := srv.Client().Get(srv.URL)
		if err != nil {
			b.Error(err)
			continue
		}
		_, err = io.Copy(ioutil.Discard, res.Body)
		if err != nil {
			b.Error(err)
		}
	}
}

func BenchmarkHTTPS(b *testing.B) {
	srv := httptest.NewTLSServer(h)
	defer srv.Close()

	b.ResetTimer()
	for i := 0 ; i < b.N ; i++ {
		res, err := srv.Client().Get(srv.URL)
		if err != nil {
			b.Error(err)
			continue
		}

		_, err = io.Copy(ioutil.Discard, res.Body)
		if err != nil {
			b.Error(err)
		}
	}
}

What did you expect to see?

A small loss on https.

What did you see instead?

A big loss on https :

BenchmarkHTTP-8    	      30	  41739281 ns/op
BenchmarkHTTPS-8   	      10	 148254359 ns/op

I know https is expected to be slower than http. But this seems to be really slow.

[davecheney]

3.5x slowdown, considering you’ve removed all network latency, sounds reasonable to me.

[bradfitz]

This bug is also a bit too vague to be actionable.

It's also somewhat of a dup of more specific bugs #21525, #22809, #20058, #19840, #22807, #22806, #20967, and a dozen others.

I'm going to close this one, but feel free to file other specific issues.

[gfyrag]

@bradfitz Yes, this was more a question than a bug. I found some others issues like those you mentionned, but most of them talk about tls handshake, which, i think is a problem with many small https request. In this case, the requests fetch 100 MB of data each time. Some of them talk about arm64 architecture which is not relevant in this case.

@davecheney Thks for the answer. I tought the slowdown will be of few percent (many blog post on the net seems to show that), but i was wrong.

[davecheney]

@davecheney Thks for the answer. I tought the slowdown will be of few percent (many blog post on the net seems to show that), but i was wrong.

once network latency is added, I expect the benchmarks would show a smaller difference.

[xp-1000]

Hi,
I have a very simple code which retrieve one metric from aws clouwatch with the aws go sdk :

svc := cloudwatch.New(session.New(), &aws.Config{Region: aws.String(region)})
        dur, _ := time.ParseDuration("300s")
        params := &cloudwatch.GetMetricStatisticsInput{
                StartTime:  aws.Time(time.Now().Add(-dur)), // Required
                EndTime:    aws.Time(time.Now()),           // Required
                MetricName: aws.String(metric_name),        // Required
                Namespace:  aws.String("AWS/ELB"),          // Required
                Period:     aws.Int64(300),                 // Required
                Statistics: []*string{ // Required
                        aws.String(metric_stat), // Required
                },
                Dimensions: []*cloudwatch.Dimension{
                        { // Required
                                Name:  aws.String("LoadBalancerName"), // Required
                                Value: aws.String(elb_name),           // Required
                        },
                },
                //Unit: aws.String("Count"),
        }
        resp, err := svc.GetMetricStatistics(params)

until now I compiled the program with go 1.8 and it works very fine :

time ./elb-check.go187 eu-west-1 test-elb Latency Average
{
Datapoints: [{
Average: 0.15102177378775059,
Timestamp: 2018-02-20 11:01:00 +0000 UTC,
Unit: "Seconds"
}],
Label: "Latency"
}

real 0m0.057s
user 0m0.028s
sys 0m0.008s

But now I upgraded my go package to 1.9, I noticed that time execution increased to more than 2x compared to 1.8 binary without any change in the code :

time ./elb-check.go19 eu-west-1 test-elb Latency Average
{
Datapoints: [{
Average: 0.15102177378775059,
Timestamp: 2018-02-20 11:01:00 +0000 UTC,
Unit: "Seconds"
}],
Label: "Latency"
}

real 0m0.123s
user 0m0.104s
sys 0m0.000s

the cpu consumption is also higher, I suspect the overhead comes from the SSL support in go 1.9 performed to cloudwatch to get the elb metric in my case.

Here is the pdf from pprof for 1.8 version :
out-go18.pdf

and here is the pdf for 1.10 version :
out-go110.pdf

it seems that the crypto part on new version makes much more syscall (and I/O operations) than the 1.8 version

[bradfitz]

@xp-1000, this issue is closed and thus is not tracked.

[xp-1000]

my bad @bradfitz I thought it will be better to add information to existing issue and reopen it instead of open a new one.