crypto/tls: degraded performance from 1.8 to 1.9 version

[xp-1000]

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

go version go1.9 linux/amd64
go version go1.10 linux/amd64

Does this issue reproduce with the latest release?

yes

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

GOARCH="amd64"
GOBIN=""
GOCACHE="/home/user/.cache/go-build"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/user/go"
GORACE=""
GOROOT="/usr/lib/go"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
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"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build843745536=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I use a very simple program created in December 2016 which use aws-go-sdk to get a metric on ELB.
It has been compile with go 1.8 and there is no problem until now.
I had to re-compiled it recently (with go 1.9) to add changes and I noticed a degradation of the performance.
Since I also tested go 1.10 and there I noticed the same behavior as for 1.9 version.
The code is exactly the same but 1.9/1.10 binary version execution time is more than 2x greater than with the 1.7/1.8 binary version.

package main

import (
	"fmt"
	"github.com/aws/aws-sdk-go/aws"
	"github.com/aws/aws-sdk-go/aws/session"
	"github.com/aws/aws-sdk-go/service/cloudwatch"
	"os"
	"time"
)

func main() {

	region := os.Args[1]
	elb_name := os.Args[2]
	metric_name := os.Args[3]
	metric_stat := "Sum"

	if len(os.Args) > 4 {
		metric_stat = os.Args[4]
	}
	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)

	if err != nil {
		panic(err)
	}

	fmt.Println(resp)
}

i.e. result of a test run for each version :
for 1.8.7 version :

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

for 1.10 version :

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

I suspect it is linked to the ssl request made to cloudwatch and so the issue #23727

Here is a pprof cpu pdf for 1.8 version :
out-go18.pdf

And the same for 1.10 version :
out-go110.pdf

What did you expect to see?

Almost the same performance / time execution.

What did you see instead?

An increase of the time execution and the resource consumption

Thanks

[agnivade]

@xp-1000 - Did you get a chance to check this with 1.11.2 ?

[xp-1000]

Hello @agnivade,
I just tested :

time ./zabbix-aws-cloudwatch-1.8.7 -region=eu-west-1 -metric=HealthyHostCount -namespace=AWS/ELB -dimensions='Name=LoadBalancerName,Value=elb-test' -stat=Minimum -no-data-value=0
1

real    0m0.051s
user    0m0.040s
sys     0m0.004s

time ./zabbix-aws-cloudwatch-1.11.2 -region=eu-west-1 -metric=HealthyHostCount -namespace=AWS/ELB -dimensions='Name=LoadBalancerName,Value=elb-test' -stat=Minimum -no-data-value=0
1

real    0m0.128s
user    0m0.108s
sys     0m0.008s

it seems not better.
I confirm the code is the same, only golang version changes.

[agnivade]

AFAIU, your code makes a network request to cloudwatch and gets some results. This is very much dependent on your network speed. If you say that the problem is with crypto/tls in general, then any tls connection should show the same delay. Ideally, we would want the network part out of the equation by setting up a local server. Your current repro, as it stands is a very generalised one without pointing towards any particular part of crypto/tls.

I will leave it for others to investigate.

[agnivade]

@xp-1000 - Just wanted to check in on this. If you can shorten the code to something that does not need to have an aws cloudwatch setup, it will help us investigate this faster.

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)