I've been struggling the last couple of days with a problem which I am not sure if its Golang's limitation or I am doing sth completely wrong.
Experiment: I am trying to benchmark the time needed for making a simple HTTP GET request to an external server. (I am hosting on EKS a web app)
I have made a Python implementation using simple requests module:
import requests
import time
start = time.time()
r = requests.get('https://httpbin.org/net')
end = time.time()
print(f'Time taken: {(end - start)*1000}ms')
Output:
Time taken: 338.42525ms
On average the time is needed for this URL is ~320ms.
Now the Golang equivalent:
import (
"fmt"
"net/http"
"os"
"time"
"github.com/go-resty/resty/v2"
)
func main() {
startTime := time.Now()
tr := &http.Transport{
MaxIdleConns: 100,
IdleConnTimeout: 30 * time.Second,
TLSHandshakeTimeout: 10 * time.Second,
MaxConnsPerHost: 1000,
//DisableKeepAlives: true,
MaxIdleConnsPerHost: 1000,
}
resp, _ := resty.New().SetTransport(tr).R().EnableTrace().SetHeader("Accept", "application/json").Get(os.Args[1])
endTime := time.Since(startTime)
fmt.Println("Total Time", endTime)
fmt.Println("Request Fire Time", resp.Request.Time)
fmt.Println("Response Received Time (body not read yet)", resp.ReceivedAt())
fmt.Println("Diff request fire & receive", resp.Time())
Output:
Total Time 310.143542ms
Request Fire Time 2022-08-01 11:43:16.750401 +0300 EEST m=+0.000985376
Response Received Time (body not read yet) 2022-08-01 11:43:17.060387 +0300 EEST m=+0.310971126
Diff request fire & receive 309.724667ms
Note I am using go-resty (but the behaviour is similar to native net/http package.
As you see, for this URL (which is public and not HTTPS), both worlds compete the same. Things are starting to change when I am using my custom web app which is hosted on EKS (I am using VPN to access it from my local machine).
Same code with only URL change using HTTPS (so TLSHandshake is involved) reports back the following numbers:
Python program:
Time taken: 578.6697864532471ms
Golang program
Total Time 761.919125ms
Request Fire Time 2022-08-01 11:49:10.911217 +0300 EEST m=+0.000936917
Response Received Time (body not read yet) 2022-08-01 11:49:11.673035 +0300 EEST m=+0.762752167
Diff request fire & receive 205.553333ms
So, why is there such a huge change between them? (~250ms) In general I am using python asyncio to spin up concurrently such requests and at the same time go routines to achieve it in Golang. So my Golang program takes around 1minute and20s to complete a bunch of 100 URLs, while Python takes only ~8s.
What I don't understand also is the statistics from go-resty:
While the time measuring using simple time.Now() reports that from the time I sent the request till I received it takes ~800ms, the Time() method of the resty client says that the actual response took ~240ms which according to the documentation doesn't make sense.
So how are these numbers sum up to match each other? Total time is ~250ms but the time measured in my code using time.Now() and time.Since(start) says ~800ms. I have just put this code to measure it:
start := time.Now()
http_client.Get(url)
end := time.Since(start)
The http_client.Get(url) simply is doing the following:
tr := &http.Transport{
MaxIdleConns: 100,
IdleConnTimeout: 30 * time.Second,
TLSHandshakeTimeout: 10 * time.Second,
MaxConnsPerHost: 1000,
//DisableKeepAlives: true,
MaxIdleConnsPerHost: 1000,
}
resp, err := NewClient().SetTransport(tr).R().EnableTrace().SetHeader("Accept", "application/json").Get(url)
fmt.Println("Response Info:")
fmt.Println(" Error :", err)
fmt.Println(" Request time:", resp.Request.Time)
fmt.Println(" Status Code:", resp.StatusCode())
fmt.Println(" Status :", resp.Status())
fmt.Println(" Proto :", resp.Proto())
fmt.Println(" Time :", resp.Time())
fmt.Println(" Received At:", resp.ReceivedAt())
//fmt.Println(" Body :\n", resp)
fmt.Println()
// Explore trace info
fmt.Println("Request Trace Info:")
ti := resp.Request.TraceInfo()
fmt.Println(" DNSLookup :", ti.DNSLookup)
fmt.Println(" ConnTime :", ti.ConnTime)
fmt.Println(" TCPConnTime :", ti.TCPConnTime)
fmt.Println(" TLSHandshake :", ti.TLSHandshake)
fmt.Println(" ServerTime :", ti.ServerTime)
fmt.Println(" ResponseTime :", ti.ResponseTime)
fmt.Println(" TotalTime :", ti.TotalTime)
fmt.Println(" IsConnReused :", ti.IsConnReused)
fmt.Println(" IsConnWasIdle :", ti.IsConnWasIdle)
fmt.Println(" ConnIdleTime :", ti.ConnIdleTime)
fmt.Println(" RequestAttempt:", ti.RequestAttempt)
fmt.Println(" RemoteAddr :", ti.RemoteAddr.String())
Response Info:
Error : <nil>
Request time: 2022-08-01 11:08:01.772263 +0300 EEST m=+0.019878460
Status Code: 200
Status : 200 OK
Proto : HTTP/2.0
Time : 252.098375ms
Received At: 2022-08-01 11:08:02.594281 +0300 EEST m=+0.841889668
Request Trace Info:
DNSLookup : 2.92825ms
ConnTime : 458ns
TCPConnTime : 174.664125ms
TLSHandshake : 203.444625ms
ServerTime : 251.888542ms
ResponseTime : 209.375µs
TotalTime : 252.098375ms
IsConnReused : true
IsConnWasIdle : true
ConnIdleTime : 76.292µs
RequestAttempt: 1
RemoteAddr : 10.0.1.178:443
{"level":"info","ts":1659341282.597458,"msg":"Elapsed time to get network response: 826.428334ms"}