API takes longer despite the use of concurrency | Discord Gophers | Page 1

tidal holly Dec 27, 2023, 5:24 AM

#

I have the following API which takes an array of ranges of IP addresses and performs concurrent API calls on all of them. Here is the code:

func handler(w http.ResponseWriter, r *http.Request) {
    var ipRanges ScanApiBody
    decoder := json.NewDecoder(r.Body)
    if err := decoder.Decode(&ipRanges); err != nil {
        http.Error(w, err.Error(), http.StatusBadRequest)
        w.WriteHeader(http.StatusBadRequest)
        return
    }
    if len(ipRanges.Ranges) == 0 {
        http.Error(w, "No Ranges Provided", http.StatusBadRequest)
        w.WriteHeader(http.StatusBadRequest)
        return
    }
    client := &http.Client{
        Transport: &digest.Transport{
            Username: "root",
            Password: "root",
        },
    }

    success := 0
    wg := sync.WaitGroup{}
    for ri := 0; ri < len(ipRanges.Ranges); ri++ {
        ipRange := ipRanges.Ranges[ri]
        for ip := ipRange.Start; !ip.Equal(ipRange.End); ip = incrementIP(ip) {
            wg.Add(1)
            go func(client *http.Client, ip net.IP) {
                defer wg.Done()
                _, err := checkIpForDevice(client, ip)
                if err != nil {
                    log.Println(err)
                } else {
                    success++
                }
            }(client, ip)
        }
    }
    wg.Wait()
    w.Write([]byte(fmt.Sprintf("Successfull: %v", success)))

}

I am sure there is some basic mistake since my knowledge of concurrency in Go is barely 1-2 days old. I am noticing that if I add more and more ranges of IP addresses, the API takes longer and longer. I expect it to be basically the same across the board since all API calls are being made at the same time.

What might I be doing wrong? Is my approach incorrect?

raven dune Dec 27, 2023, 9:22 AM

#

Your purpose is to call the interfaces of multiple IPs at the same time when there are many IPs. Don’t you want to have a sequence?

tidal holly Dec 27, 2023, 9:27 AM

#

No. Thats not important at the moment.

raven dune Dec 27, 2023, 9:28 AM

#

May I ask, what is your purpose?

#

My english is not good, please forgive

tidal holly Dec 27, 2023, 9:31 AM

#

There are thousands of "devices" in a data center and the technician can run this API to scan several ranges of IP address to detect if there are any devices.

The detection is done by calling the IP address like this: http://10.0.105.1/check-device-status

dawn raptor Dec 27, 2023, 11:52 AM

#

One approach I used in my projects is that to mesure times between 2 critical points. For example, I got a slow program running and was wondering what the bottleneck. It appear it was a part of the algorithm that was very slow to his time complexity (n²) .
The package is very simple (with the current code, it doesn't even require to be a package tbh):

type Timer struct {
    start time.Time
}

func NewTimer() *Timer {
    return &Timer{
        start: time.Now(),
    }
}

func (t *Timer) Reset() {
    t.start = time.Now()
}

func (t *Timer) Elapsed() time.Duration {
    return time.Since(t.start)
}

Example of a function that use the timer:

func (a *AnalyticsEngine) goThroughAllChampions(ctx context.Context, apply func(ctx context.Context, championID int, errChan chan<- error, sm *sync.Map)) (*sync.Map, error) {
    wg := &sync.WaitGroup{}
    totalChampions := len(a.data.ChampionsStats)
    wg.Add(totalChampions)
    errChan := make(chan error, totalChampions)
    sm := &sync.Map{}
    t := timer.NewTimer() // INIT TIMER
    defer func() {
        printer.Info("goThroughAllChampions done in %s", t.Elapsed())
    }()
    for _, c := range a.data.ChampionsStats {
        champID := c
        go func() {
            apply(ctx, champID.GetIntID(), errChan, sm)
            wg.Done()
        }()
    }

    go func() {
        wg.Wait()
        close(errChan)
    }()

    var errs AggregateErrors
    for err := range errChan {
        errs = append(errs, err)
    }
    if len(errs) == 0 {
        return sm, nil
    } else {
        return sm, errs
    }
}

So you could measure the time the API takes to respond and determine if it's the bottleneck of your application.
Note: this is a very simple solution, but not the most effective one for determining the application bottleneck.Note: this is a very simple solution, but not the most effective one for determining the application bottleneck.

tidal holly Dec 27, 2023, 9:59 PM

#

@dawn raptor I have been trying something similar since yesterday. I simplified my code to the following to see how long 10 vs 100 vs 1000 vs 10000 requests take. Here is the code:

func testHandler(c *gin.Context) {
    wg := sync.WaitGroup{}
    count := 0
    for j := 0; j < 1000; j++ {
        wg.Add(1)
        go func(index int) {
            defer wg.Done()
            s := time.Now()
            http.Get("https://jsonplaceholder.typicode.com/todos/1")
            log.Printf("Time Elapsed: %v", time.Since(s))
            count++
        }(j)
    }
    wg.Wait()
    log.Printf("API Count: %v", count)
}

All logs in the terminal are obviously unordered in terms of the index but I have noticed that the time elapsed takes longer as more requests are made.
10 -> First request takes 0.51s to 0.52s
100 -> First request takes 0.53s to 0.56s
1000 -> First request takes 1s and the last takes 3s
10000 -> First request takes 7s and goes up to 40s and then I get a bunch of errors and the server stops

Its almost unnoticeable in 10 and 100 requests/loops but becomes musch evident in 1000+ requests. What do you think I may be doing incorrectly or perhaps understanding incorrectly?

dawn raptor Dec 27, 2023, 10:29 PM

#

You are sure isn't jsonplaceholder that is limiting your request ? If they have a rate limiter or smth like that?

tidal holly Dec 27, 2023, 10:49 PM

#

I doubt it. I have tried other APIs too and I have similar results.

But more importantly, shouldn't the first 100 API calls take the same time if there is a rate limit.

And also, rate limitation generally cancels the request with Code 429. In this case, all API calls have nil error.

dawn raptor Dec 27, 2023, 11:06 PM

#

I kept the same URL and I don't get the exact same result with this code:

package main

import (
    "log"
    "net/http"
    "sync"
    "sync/atomic"
    "time"
)

func testHandler(n int) {
    wg := sync.WaitGroup{}
    count := atomic.Int32{}
    wg.Add(n)
    s := time.Now()
    for j := 0; j < n; j++ {
        go func(index int) {
            defer wg.Done()
            http.Get("https://jsonplaceholder.typicode.com/todos/1")
            count.Add(1)
        }(j)
    }
    wg.Wait()
    log.Printf("Time Elapsed: %v for %d iterations", time.Since(s), n)
    log.Printf("API Count: %v", count.Load())
}

func main() {
    cases := []int{1, 10, 100, 1000, 10000}
    for _, c := range cases {
        testHandler(c)
    }
}

#

Gives

2023/12/28 00:06:25 Time Elapsed: 94.259375ms for 1 iterations
2023/12/28 00:06:25 API Count: 1
2023/12/28 00:06:25 Time Elapsed: 18.605808ms for 10 iterations
2023/12/28 00:06:25 API Count: 10
2023/12/28 00:06:25 Time Elapsed: 43.856995ms for 100 iterations
2023/12/28 00:06:25 API Count: 100
2023/12/28 00:06:25 Time Elapsed: 661.514039ms for 1000 iterations
2023/12/28 00:06:25 API Count: 1000
2023/12/28 00:06:31 Time Elapsed: 5.871393578s for 10000 iterations
2023/12/28 00:06:31 API Count: 10000

tidal holly Dec 27, 2023, 11:38 PM

#

@dawn raptor I tried your code and for 1 to 1000, it varies between 0.5s and 1.5s. But for 10000, it is still 40s.
Could it be that I am doing it in an http server? I am using gin.

#

2023/12/28 04:39:42 Time Elapsed: 505.130917ms for 1 iterations
2023/12/28 04:39:42 API Count: 1
2023/12/28 04:39:42 Time Elapsed: 167.604708ms for 10 iterations
2023/12/28 04:39:42 API Count: 10
2023/12/28 04:39:43 Time Elapsed: 210.079791ms for 100 iterations
2023/12/28 04:39:43 API Count: 100
2023/12/28 04:39:45 Time Elapsed: 2.725200583s for 1000 iterations
2023/12/28 04:39:45 API Count: 1000
2023/12/28 04:40:32 Time Elapsed: 46.638408083s for 10000 iterations
2023/12/28 04:40:32 API Count: 10000

This is my output

dawn raptor Dec 28, 2023, 3:42 PM

#

The problem definitely doesn't come from the code or the API you are contacting. What are you running your code on ?

tidal holly Dec 28, 2023, 9:10 PM

#

My personal M1 Pro MacBook

dawn raptor Dec 28, 2023, 9:21 PM

#

Have you an high speed internet connection? That's very surprising.
The result I got seems to follow some logical results. For example, 1000 requests is 661 ms. We can expect around 6.61 sec for 10000 requests. In reality it has been slightly faster. It's still all good.
On the other hand, your results don't follow any particular logic, which shows that something external to the code is interfering.

tidal holly Dec 28, 2023, 9:37 PM

#

No. My internet connection is decent enough. If that was the problem, shouldnt it also affect 1000 API calls or any number lower than that?

wanton willow Dec 29, 2023, 7:12 AM

#

Nvm its the api of jsonplaceholder
it's giving an 403 after a certain limit

tidal holly Dec 29, 2023, 8:00 AM

#

wanton willow Nvm its the api of jsonplaceholder it's giving an 403 after a certain limit

I dont get that error. Do you know what the limit is?

wanton willow Dec 29, 2023, 8:01 AM

#

I don't get it always so it must be greater than 10000. For me it was sometimes faster to build it first

tidal holly Dec 29, 2023, 8:02 AM

#

I tried both ways and 10k requests take 40+ seconds. I never get any error.

wanton willow Dec 29, 2023, 8:03 AM

#

package main

import (
    "context"
    "io"
    "log"
    "net/http"
    "sync"
    "sync/atomic"
    "time"

    "golang.org/x/sync/semaphore"
)

func testHandler(n int) {
    wg := sync.WaitGroup{}
    ctx := context.TODO()
    count := atomic.Int32{}
    sem := semaphore.NewWeighted(200)
    wg.Add(n)
    s := time.Now()
    for j := 0; j < n; j++ {
        go func(index int) {
            sem.Acquire(ctx, 1)
            defer sem.Release(1)
            defer wg.Done()
            defer count.Add(1)
            resp, err := http.Get("https://jsonplaceholder.typicode.com/todos/1")
            if err != nil {
                log.Printf("err: %v", err)
                return
            }
            defer resp.Body.Close()
            if resp.StatusCode >= 300 {
                log.Printf("status: %d", resp.StatusCode)
            }

            io.Copy(io.Discard, resp.Body)
        }(j)
    }
    wg.Wait()
    log.Printf("Time Elapsed: %v for %d iterations", time.Since(s), n)
    log.Printf("API Count: %v", count.Load())
}

func main() {
    cases := []int{1, 10, 100, 1000, 10000}
    for _, c := range cases {
        testHandler(c)
    }
}

Can you try this? I added a semaphore to set a maximum number of go routines. You can change the 200 it's arbitrary

tidal holly Dec 29, 2023, 8:06 AM

#

Without building:

2023/12/29 13:05:22 Time Elapsed: 63.113ms for 1 iterations
2023/12/29 13:05:22 Time Elapsed: 21.451875ms for 10 iterations
2023/12/29 13:05:22 Time Elapsed: 51.730833ms for 100 iterations
2023/12/29 13:05:23 Time Elapsed: 1.101182041s for 1000 iterations
2023/12/29 13:05:27 Time Elapsed: 3.897459292s for 10000 iterations

With building:

2023/12/29 13:06:10 Time Elapsed: 130.830541ms for 1 iterations
2023/12/29 13:06:10 Time Elapsed: 60.722ms for 10 iterations
2023/12/29 13:06:10 Time Elapsed: 86.906542ms for 100 iterations
2023/12/29 13:06:11 Time Elapsed: 998.470167ms for 1000 iterations
2023/12/29 13:06:16 Time Elapsed: 5.248612667s for 10000 iterations

wanton willow Dec 29, 2023, 8:07 AM

#

Yea it varies from run to run

#

2023/12/29 09:06:26 err: Get "https://jsonplaceholder.typicode.com/todos/1": http2: client connection force closed via ClientConn.Close

If you try that multiple times now you will get something like this from their API

tidal holly Dec 29, 2023, 8:08 AM

#

Thats understandable.

So the fault was more with the external API rather than my implementation.

wanton willow Dec 29, 2023, 8:09 AM

#

Well what can happen is that you have too many go routines at the same time, so that the scheduler will need to switch more often. This can take some time in some cases

tidal holly Dec 29, 2023, 8:09 AM

#

I am getting a bunch of 403 errors on my 3rd try now. Not sure why I didnt get these with my code.

wanton willow Dec 29, 2023, 8:09 AM

#

Thats why I added the semaphore

#

Because the semaphore made it faster. Also you always have to read and close the response body

#

https://pkg.go.dev/net/http

The caller must close the response body when finished with it:

lucid cloakBOT Dec 29, 2023, 8:12 AM

#

Package net/http

tidal holly Dec 29, 2023, 8:12 AM

#

Thanks. I was trying to implement worker pools but I guess this is a decent enough solution.

wanton willow Dec 29, 2023, 8:13 AM

#

You can also look how many file descriptors your program will take

#

Each request which is opened at the same time means a new file descriptor

tidal holly Dec 29, 2023, 8:14 AM

#

Can you point me to a good resource regarding that?

wanton willow Dec 29, 2023, 8:15 AM

#

Under Linux you can use lsof to list all descriptors of a running program

#

Not sure about Mac OS

tidal holly Dec 29, 2023, 8:16 AM

#

Okay. I'll do some research about that.

tidal holly Dec 29, 2023, 9:21 AM

#

@wanton willow I noticed something. Perhaps you can offer some insight. If I only log the elapsed time of each individual goroutine (lets say there 1000 in total), the time goes from a few hundred milliseconds to a few seconds.

This trend is there in 10, 100 and 10k too.

Shouldn't all goroutines take the same (or similar) amount of time since they are doing almost identical work?

wanton willow Dec 29, 2023, 9:25 AM

#

It depends what task it is. For example on the above routine it depends on how fast the server can answer.

#

When the server can't handle that many requests at the same time they will have to wait

tidal holly Dec 29, 2023, 9:27 AM

#

How can I check that this is indeed a sever related issue and not a mistake in my code?

wanton willow Dec 29, 2023, 9:28 AM

#

For example lets say it can handle 100 requests at the same time. When it can't handle any more requests it will just hold the request until there is some free space

#

For this paticular thing? I would probably just spin up a test server and always answer with 204

tidal holly Dec 29, 2023, 9:31 AM

#

wanton willow For example lets say it can handle 100 requests at the same time. When it can't ...

Thats probably it.

wanton willow Dec 29, 2023, 9:31 AM

#

You might take a look at this: https://pkg.go.dev/net/http/httptest#Server

lucid cloakBOT Dec 29, 2023, 9:31 AM

#

net/http/httptest: Server

wanton willow Dec 29, 2023, 9:32 AM

#

Or well you can test it against a cluster because that would be more like your real world

#

Because on your starting example you were calling multiple servers instead of just one

tidal holly Dec 29, 2023, 9:34 AM

#

Yes. That is my use case. I am pinging 3000+ servers to check their status.

wanton willow Dec 29, 2023, 9:35 AM

#

Yes and there could be mutliple bottlenecks on your example

#

The servers or the infrastructure (some switch, a firewall, someone who does dpi)

#

Some client site antivirus

tidal holly Dec 29, 2023, 9:38 AM

#

Its possible but unlikely. We already have a 3rd party tools that does the scanning successfully and in 3-5 seconds. But that tool has some other shortcomings (company's preference) so I am trying to set up our own version.

wanton willow Dec 29, 2023, 9:40 AM

#

My best guess would be to start with just the simple request

#

In the real world environment

tidal holly Dec 29, 2023, 9:44 AM

#

I am VPN'ed into the data centre. I'll keep trying different methods. I just didnt expect it to be this complicated.

wanton willow Dec 29, 2023, 9:44 AM

#

Oh yea make sure that you are reading and closing the request body

tidal holly Dec 29, 2023, 9:45 AM

#

Yes. I am doing that.

wanton willow Dec 29, 2023, 9:46 AM

#

You can also use https://pkg.go.dev/net/http/pprof to investigate some metrics

#API takes longer despite the use of concurrency