Why is fasthttp.Client slow when used concurrently to consume an API?

Question

it is first case.

var fastClient fasthttp.Client

fastClient = fasthttp.Client{
    ReadTimeout: 500 * time.Millisecond,
    MaxConnsPerHost: 500,
}

runtime.GOMAXPROCS(1)

for i := 0; i < 500; i++ {
    req := fasthttp.AcquireRequest()
    req.Header.SetMethod("GET")
    req.SetRequestURI(TEST_REST_API)
    res := fasthttp.AcquireResponse()
    
    start := time.Now()
    err := client.Do(req, res)
    ms := time.Since(start).Milliseconds()

    fasthttp.ReleaseRequest(req)
    fasthttp.ReleaseResponse(res)

    fmt.Printf("%v %v", ms, string(res.Header.Peek("x-real-service-time")))
}

and it is second case.

var fastClient fasthttp.Client

fastClient = fasthttp.Client{
    ReadTimeout: 500 * time.Millisecond,
    MaxConnsPerHost: 500,
}

runtime.GOMAXPROCS(1)

for i := 0; i < 500; i++ {
    go func(id int, c *fasthttp.Client) {
       req := c.AcquireRequest()
       req.Header.SetMethod("GET")
       req.SetRequestURI(TEST_REST_API)
       res := c.AcquireResponse()

       start := time.Now()
       err := client.Do(req, res)
       ms := time.Since(start).Milliseconds()

       c.ReleaseRequest(req)
       c.ReleaseResponse(res)

       fmt.Printf("%v %v %v", id, ms, string(res.Header.Peek("x-real-service-time")))
    }(i, &fastClient)

    // waiting for end all goroutine
}

x-real-service-time is a header that records the time it took for the server to process the actual request and respond.

in first case, ms is almost same with x-real-service-time. in second case, ms is too slower than x-real-service-time, and it gets slower and slower with each id.

Can you explain the reason for these differences? And I hope the difference between ms and x-real-service-time is small in the second case as well. How should I tune it?

EDIT: result for first case.

id: 166 | ms: 115 | x-real-service-time : 105
id: 167 | ms: 103 | x-real-service-time : 97
id: 168 | ms: 89 | x-real-service-time : 73
id: 169 | ms: 92 | x-real-service-time : 76
id: 170 | ms: 79 | x-real-service-time : 73
id: 171 | ms: 81 | x-real-service-time : 73
id: 172 | ms: 84 | x-real-service-time : 76
id: 173 | ms: 84 | x-real-service-time : 78
id: 174 | ms: 81 | x-real-service-time : 73
id: 175 | ms: 82 | x-real-service-time : 76
id: 176 | ms: 82 | x-real-service-time : 75
id: 177 | ms: 80 | x-real-service-time : 74
id: 178 | ms: 79 | x-real-service-time : 71
id: 179 | ms: 75 | x-real-service-time : 69
id: 180 | ms: 87 | x-real-service-time : 78
id: 181 | ms: 81 | x-real-service-time : 72
...

result for second case.

id: 486 | ms: 516 | x-real-service-time : 72
id: 361 | ms: 620 | x-real-service-time : 100
id: 349 | ms: 620 | x-real-service-time : 96
id: 417 | ms: 621 | x-real-service-time : 100
id: 3 | ms: 631 | x-real-service-time : 76
id: 227 | ms: 634 | x-real-service-time : 90
id: 152 | ms: 639 | x-real-service-time : 77
id: 138 | ms: 640 | x-real-service-time : 78
id: 139 | ms: 640 | x-real-service-time : 84
id: 144 | ms: 640 | x-real-service-time : 79
...
id: 267 | ms: 783 | x-real-service-time : 75
id: 195 | ms: 779 | x-real-service-time : 73
id: 465 | ms: 781 | x-real-service-time : 76
id: 420 | ms: 781 | x-real-service-time : 74
id: 334 | ms: 782 | x-real-service-time : 112
id: 14 | ms: 780 | x-real-service-time : 69
id: 430 | ms: 781 | x-real-service-time : 75
id: 372 | ms: 782 | x-real-service-time : 78
id: 224 | ms: 778 | x-real-service-time : 107
...
id: 481 | ms: 825 | x-real-service-time : 67
id: 105 | ms: 823 | x-real-service-time : 75
id: 467 | ms: 825 | x-real-service-time : 71
id: 67 | ms: 825 | x-real-service-time : 73
id: 460 | ms: 828 | x-real-service-time : 77
id: 142 | ms: 827 | x-real-service-time : 78
id: 58 | ms: 828 | x-real-service-time : 71
id: 311 | ms: 833 | x-real-service-time : 78
id: 414 | ms: 833 | x-real-service-time : 71
id: 289 | ms: 836 | x-real-service-time : 77
...
id: 323 | ms: 1019 | x-real-service-time : 201
id: 211 | ms: 1015 | x-real-service-time : 209
id: 220 | ms: 1015 | x-real-service-time : 203
id: 275 | ms: 1021 | x-real-service-time : 216
id: 477 | ms: 1019 | x-real-service-time : 207
id: 160 | ms: 1017 | x-real-service-time : 197
id: 398 | ms: 1020 | x-real-service-time : 199
id: 253 | ms: 1017 | x-real-service-time : 201
id: 74 | ms: 1019 | x-real-service-time : 204
id: 422 | ms: 1021 | x-real-service-time : 205

id : loop number(variable i)

ms : The time it takes for a client to receive a response after making a request (millisecond)

x-real-service-time: Time spent actually processing on the server (millisecond)

Answer 1

you only use one cpu(runtime.GOMAXPROCS(1)),

if you use goroutine, cpu will waiting and hang,

client.Do cost most time.

there are not slow but start time too early.

this is why result for second case. id⬆ -> time⬆