Http request using Go (go-resty or net/http) is much slower than Python requests

1.8k Views Asked by At

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



0

There are 0 best solutions below