Performance issue with GO http client

[kiran chitturi]

Hi,

I have been using GO http client to send requests to a Jetty server hosting a webapp. Based on my observations so far, the latencies with GO client has been increasing over time and the total time taken to finish certain number of requests is more when compared to basic 'ab' command-line tool. I am hoping to find the reason, whether it is in my code or in the GO http client.

GO code to send API GET requests to a server with a concurrency limit is pasted below. The code I wrote (pasted below) sends a total of 100k requests to the server, while making sure that there are a total of 100 active requests at any point of time. I am creating one client and re-using it for every request.

The execution times with the below code:

user@dev1:test_benchmark$ ./test_api_requests 

2014/02/27 17:52:47 Starting api requests to url http://dev:8765/lucid/api/v1 

2014/02/27 17:53:56 Waiting for channels to finish

2014/02/27 17:53:58 Closing response channel

2014/02/27 17:53:58 Total time taken to finish 100000 requests is 70.643425 seconds

Using 'ab' benchmark tool for the same url and 100 concurrent requests, the results are:

user@dev1:test_benchmark$ ab -n 100000 -c 100 http://dev:8765/lucid/api/v1

Time taken for tests:   46.083 seconds

 

Full results at (https://gist.github.com/kiranchitturi/e7e1c75a35a22ef69b52#file-1-bash).

When I increase the number of concurrent requests, the total time taken is quite high between 'GO code' and 'ab' tool.

I have used the same code as below but I made 100k 'POST' requests instead of GET and I plotted the avg. latency times for one second in the below chart. The red line is the avg. latency for requests made from 'ab' tool and green line is the avg. latency per second from 'Go code'.  Go code for POST requests is at (https://gist.github.com/kiranchitturi/e7e1c75a35a22ef69b52#file-base-go).

I also have similar GO code which reads from a file and sends POST requests for data read from each line. For a total of 2.7 million+ requests with 80 http requests (go routines) active at any point of time, the plot for latency time vs count looks as shown in the image below. The latency times increased steeply when the total amount of requests have also increased. There are outliers in the graph below which I assumed are GC issues on the server side.


I am wondering if the problem is with my code or if I could optimize my code any better to get better performance. Is it possible to achieve better performance with GO http client ? 

Please let me know your suggestions. Thank you. 

package main

import (

        "github.com/lucidworks/base"

        "log"

        "net/http"

        "sync/atomic"

        "runtime"

        "time"

)

var tr = &http.Transport{

        MaxIdleConnsPerHost: 90,

}

var client = &http.Client{

        Transport: tr,

}

var MaxRoutines = 100

var sem = make(chan int, MaxRoutines)

var counter uint64 = 0

func init() {

        for i := 0; i < MaxRoutines; i++ {

                sem <- 1

        }

}

// Read channel

func read_channel(HttpResponse chan base.HTTPResponse, c chan int) {

        for _ = range HttpResponse {

                atomic.AddUint64(&counter, 1)

        }

        c <- 0

        close(c)

}

func main() {

        runtime.GOMAXPROCS(runtime.NumCPU())

    TotalRequests := 100000

        IssuedGoroutines := 0

        HttpResponse := make(chan base.HTTPResponse)

        c := make(chan int)

        go read_channel(HttpResponse, c)

        url := "http://dev2vm28:8765/lucid/api/v1"

        log.Printf("Starting api requests to url %s \n", url)

        start_time := time.Now()

        for {

                <-sem // Read from channel. Wait if channel is empty.

                go make_requests(url, HttpResponse)

                IssuedGoroutines++

                if IssuedGoroutines == TotalRequests {

                        // Exit once total requests have been made

                        break

                }

        }

        log.Println("Waiting for channels to finish")

        // Close response once all the goroutines have finished and have been read

        for {

                counterFinal := atomic.LoadUint64(&counter)

                if counterFinal == uint64(IssuedGoroutines) {

                        log.Println("Closing response channel")

                        close(HttpResponse)

                        break

                }

        }

        // Read channel c1 until it is closed.

        for _ = range c {

        }

        execution_duration := time.Since(start_time)

        log.Printf("Total time taken to finish %d requests is %f seconds\n", TotalRequests, execution_duration.Seconds())

}

func make_requests(url string, response chan base.HTTPResponse) {

        resp, err := base.GetHTTP(client, url, nil)

        if err != nil {

                log.Fatal(err.Error())

        }

        response <- resp

        sem <- 0 // Fill the channel if http request is finished

}

  The library functions that actually do the HTTP request are:

     type HTTPResponse struct {

        Body        []byte

        Duration    float64

        ReqUnixTime float64

     }

/*

Get request for an Url. If `get_body` param is set to true, then send the body otherwise send nil

*/

func GetHTTP(client *http.Client, api_url string, params map[string]interface{}) (HTTPResponse, error) {

    if params != nil {

        parsed_url, _ := url.Parse(api_url)

        values := parsed_url.Query()

        for k, v := range params {

            switch v_value := v.(type) {

            default:

                logger.Debug("Unexpected type")

            case string:

                values.Add(k, v_value)

            case []string:

                for each := range v_value {

                    values.Add(k, v_value[each])

                }

            }

        }

        api_url = parsed_url.String() + "?" + values.Encode()

    }

    // Do the HTTP GET request.

    req, err := http.NewRequest("GET", api_url, nil)

    if err != nil {

        logger.Fatal("Error in creating request")

    }

    req.Header.Add("Content-type", "application/json")

    //logger.Debug("Doing the request")

    start_time := time.Now()

    resp, err := client.Do(req)

    //logger.Debug("Finished the request")

    duration := time.Since(start_time)

    //logger.Debug("Time took for GET request is %f", duration.Seconds())

    if err != nil {

        logger.Debug(err.Error())

        return HTTPResponse{}, err

    }

    data, err1 := ioutil.ReadAll(resp.Body)

    if err1 != nil {

        logger.Fatal("Errror in reading response body. Error: %s", err.Error())

    }

    resp.Body.Close()

    response := HTTPResponse{data, duration.Seconds(), float64(start_time.Unix())}

    return response, nil

}

[Tamás Gulácsi]

You should profile your program firrst, but an easy fix against garbage would be turning the design upside down: instead of creating a goroutine for each job, create n goroutines, which take the jobs from a channel, and exit only when that channel is closed.
That channel could be filled and then closed from the main goroutine. See sync.WaitGroup for waiting the workers to finish.

[kiran chitturi]

Thank you very much for your reply. 

I did profile some of my programs but I was not sure how to infer the results. Attached, please find the profile info.

The blog post helped http://golang.org/pkg/runtime/pprof/ me a bit but I could not fully understand the post first time. I will profile better and read more about pprof. 

Thanks for the design suggestion. I will take a stab at it sometime this weekend and see how it goes.

[Dmitry Vyukov]

this is a busy loop which can burn unbounded amount of cpu

 

                if counterFinal == uint64(IssuedGoroutines) {

                        log.Println("Closing response channel")

                        close(HttpResponse)

                        break

                }

        }

        // Read channel c1 until it is closed.

        for _ = range c {

        }

        execution_duration := time.Since(start_time)

        log.Printf("Total time taken to finish %d requests is %f seconds\n", TotalRequests, execution_duration.Seconds())

}

func make_requests(url string, response chan base.HTTPResponse) {

        resp, err := base.GetHTTP(client, url, nil)

        if err != nil {

                log.Fatal(err.Error())

        }

        response <- resp

        sem <- 0 // Fill the channel if http request is finished

}

  The library functions that actually do the HTTP request are:

     type HTTPResponse struct {

        Body        []byte

        Duration    float64

        ReqUnixTime float64

     }

/*

Get request for an Url. If `get_body` param is set to true, then send the body otherwise send nil

*/

func GetHTTP(client *http.Client, api_url string, params map[string]interface{}) (HTTPResponse, error) {

you need to set connection cache of the client to the concurrency level

 

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Dmitry Vyukov]

On Fri, Feb 28, 2014 at 9:41 AM, kiran chitturi
<chittur...@gmail.com> wrote:
> Thank you very much for your reply.
>
> I did profile some of my programs but I was not sure how to infer the
> results. Attached, please find the profile info.

you seem to pass a wrong binary to pprof, because function names look wrong
also you seem to be running under race detector, the race detector can
slow down programs by 10+x

> The blog post helped http://golang.org/pkg/runtime/pprof/ me a bit but I
> could not fully understand the post first time. I will profile better and
> read more about pprof.
>
> Thanks for the design suggestion. I will take a stab at it sometime this
> weekend and see how it goes.
>
>
> On Thursday, February 27, 2014 9:24:19 PM UTC-8, Tamás Gulácsi wrote:
>>
>> You should profile your program firrst, but an easy fix against garbage
>> would be turning the design upside down: instead of creating a goroutine for
>> each job, create n goroutines, which take the jobs from a channel, and exit
>> only when that channel is closed.
>> That channel could be filled and then closed from the main goroutine. See
>> sync.WaitGroup for waiting the workers to finish.
>

[kiran chitturi]

Oh, yes. I am running all this under the race detector. Let me try by not using the race detector. It is good to use race detector initially but I guess once I am sure, there are no race cases I should remove the race detector.

Thank you so much

[kiran chitturi]

So, I have build the code without using race detectors and for 2.7 M requests the total time came down from 100 minutes to 10 minutes. 

Thanks everyone for the help

[Dmitry Vyukov]

setting max number of idle connections in http.Client can help reduce it further
AFAIR, by default client caches at most 2 connections, so this test
has to close and recreate lots of connections

[kiran chitturi]

Yeah. So, I set that param in my code here (https://gist.github.com/kiranchitturi/e7e1c75a35a22ef69b52#file-test_api_requests-go-L13).