Запрос HTTP с использованием Go (go-resty или net/http) намного медленнее, чем запросы Python.

Question

Последние пару дней я боролся с проблемой, в которой я не уверен, является ли это ограничением Голанга или я делаю что-то совершенно неправильно.

Эксперимент: я пытаюсь измерить время, необходимое для отправки простого HTTP-запроса GET на внешний сервер. (Я размещаю на EKS веб-приложение)

Я сделал реализацию Python, используя простой модуль запросов:

          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')

Выход:

      Time taken: 338.42525ms

В среднем время, необходимое для этого URL, составляет ~320 мс.

Теперь эквивалент Голанга:

      
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())

Выход:

      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

Примечание. Я использую go-resty (но поведение аналогично собственному пакету net/http.

Как видите, за этот URL (публичный, а не HTTPS) оба мира конкурируют одинаково. Все начинает меняться, когда я использую свое собственное веб-приложение, размещенное на EKS (я использую VPN для доступа к нему с моей локальной машины).

Тот же код только с изменением URL-адреса с использованием HTTPS (поэтому задействован TLSHandshake) возвращает следующие числа:

      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

Итак, почему между ними такая огромная разница? (~250 мс) В общем, я использую python asyncio, чтобы одновременно запускать такие запросы и в то же время запускать подпрограммы для достижения этого в Golang. Таким образом, моя программа Golang занимает около 1 минуты и 20 секунд, чтобы заполнить группу из 100 URL-адресов, в то время как Python занимает всего ~8 секунд.

Чего я не понимаю, так это статистики от go-resty:

В то время как измерение времени с использованием простого time.Now() сообщает, что с момента отправки запроса до получения он занимает ~800 мс, метод Time() неуверенного клиента говорит, что фактический ответ занял ~240 мс, что согласно документации не имеет смысла.

Итак, как эти числа суммируются, чтобы соответствовать друг другу? Общее время составляет ~250 мс, но время, измеренное в моем коде с использованием time.Now() и time.Since(start), говорит ~800 мс. Я только что поставил этот код, чтобы измерить его:

      start := time.Now()
http_client.Get(url)
end := time.Since(start)

http_client.Get(url) просто делает следующее:

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