Go HTTP Server Performance Issue

Question

I am writing an event collector http server which would be under heavy load. Hence in the http handler I am just deserialising the event and then running the actual processing outside of the http request-response cycle in a goroutine.

With this, I see that if I am hitting the server at 400 requests per second, then the latency is under 20ms for 99 percentile. But as soon as I bump the request rate to 500 per second, latency shoots up to over 800ms.

Could anyone please help me with some ideas on what the reason could be so that I can explore more.

package controller

import (
    "net/http"
    "encoding/json"
    "event-server/service"
    "time"
)

func CollectEvent() http.Handler {
    handleFunc := func(w http.ResponseWriter, r *http.Request) {
        startTime := time.Now()
        stats.Incr("TotalHttpRequests", nil, 1)
        decoder := json.NewDecoder(r.Body)
        var event service.Event
        err := decoder.Decode(&event)
        if err != nil {
            http.Error(w, "Invalid json: " + err.Error(), http.StatusBadRequest)
            return
        }
        go service.Collect(&event)
        w.Write([]byte("Accepted"))
        stats.Timing("HttpResponseDuration", time.Since(startTime), nil, 1)
    }

    return http.HandlerFunc(handleFunc)
}

I ran a test with 1000 requests per second and profiled it. Following are the results.

(pprof) top20
Showing nodes accounting for 3.97s, 90.85% of 4.37s total
Dropped 89 nodes (cum <= 0.02s)
Showing top 20 nodes out of 162
      flat  flat%   sum%        cum   cum%
     0.72s 16.48% 16.48%      0.72s 16.48%  runtime.mach_semaphore_signal
     0.65s 14.87% 31.35%      0.66s 15.10%  syscall.Syscall
     0.54s 12.36% 43.71%      0.54s 12.36%  runtime.usleep
     0.46s 10.53% 54.23%      0.46s 10.53%  runtime.cgocall
     0.34s  7.78% 62.01%      0.34s  7.78%  runtime.mach_semaphore_wait
     0.33s  7.55% 69.57%      0.33s  7.55%  runtime.kevent
     0.30s  6.86% 76.43%      0.30s  6.86%  syscall.RawSyscall
     0.10s  2.29% 78.72%      0.10s  2.29%          runtime.mach_semaphore_timedwait
     0.07s  1.60% 80.32%      1.25s 28.60%  net.dialSingle
     0.06s  1.37% 81.69%      0.11s  2.52%  runtime.notetsleep
     0.06s  1.37% 83.07%      0.06s  1.37%  runtime.scanobject
     0.06s  1.37% 84.44%      0.06s  1.37%  syscall.Syscall6
     0.05s  1.14% 85.58%      0.05s  1.14%  internal/poll.convertErr
     0.05s  1.14% 86.73%      0.05s  1.14%  runtime.memmove
     0.05s  1.14% 87.87%      0.05s  1.14%  runtime.step
     0.04s  0.92% 88.79%      0.09s  2.06%  runtime.mallocgc
     0.03s  0.69% 89.47%      0.58s 13.27%  net.(*netFD).connect
     0.02s  0.46% 89.93%      0.40s  9.15%  net.sysSocket
     0.02s  0.46% 90.39%      0.03s  0.69%  net/http.(*Transport).getIdleConn
     0.02s  0.46% 90.85%      0.13s  2.97%  runtime.gentraceback
(pprof) top --cum
Showing nodes accounting for 70ms, 1.60% of 4370ms total
Dropped 89 nodes (cum <= 21.85ms)
Showing top 10 nodes out of 162
      flat  flat%   sum%        cum   cum%
         0     0%     0%     1320ms 30.21%  net/http.(*Transport).getConn.func4
         0     0%     0%     1310ms 29.98%  net.(*Dialer).Dial
         0     0%     0%     1310ms 29.98%  net.(*Dialer).Dial-fm
         0     0%     0%     1310ms 29.98%  net.(*Dialer).DialContext
         0     0%     0%     1310ms 29.98%  net/http.(*Transport).dial
         0     0%     0%     1310ms 29.98%  net/http.(*Transport).dialConn
         0     0%     0%     1250ms 28.60%  net.dialSerial
      70ms  1.60%  1.60%     1250ms 28.60%  net.dialSingle
         0     0%  1.60%     1170ms 26.77%  net.dialTCP
         0     0%  1.60%     1170ms 26.77%  net.doDialTCP
(pprof) 

Answer 1

The problem

I am using another goroutine because I dont want the processing to happen in the http request-response cycle.

That's a common fallacy (and hence trap). The line of reasoning appears to be sound: you're trying to process requests "somewhere else" in an attempt to handle ingress HTTP requests as fast as possible.

The problem is that that "somewhere else" is still some code which runs concurrently with the rest of your request-handling churn. Hence if that code runs slower than the rate of ingress requests, your processing goroutines will pile up essentially draining one or more resources. Which exactly—depends on the actual processing: if it's CPU-bound, it will create natural contention for the CPU between all those GOMAXPROCS hardware threads of execution; if it's bound to network I/O, it will create load on Go runtime scheruler which has to divide the available execution quanta it has on its hands between all those goroutines wanted to be executed; if it's bound to disk I/O or other syscalls you will have proliferation of OS threads created, and so on and so on…

Essentially, you are queueing the work units converted from the ingress HTTP requests, but queues do not fix overload. They might be used to absorb short spikes of overload, but this only works when such spikes are "surrounded" by the periods of load at least slightly below the maximum capacity provided by your system. The fact you're queueing is not directly seen in your case, but it's there, and it's exhibited by pressing your system past its natural capacity—your "queue" starts to grow indefinitely.

Please read this classic essay carefully to understand why your approach is not going to work in realistic production setting. Pay close attention to those pictures of the kitchen sinks.

What to do about it?

Unfortunately, it's almost impossible to give your simple solution as we're not working with your code in your settings with your workload. Still, here are a couple of directions to explore.

On the most broad scale, try to see whether you have some easily discernible bottleneck in your system which you presently cannot see. For instance, if all those concurrent worker goroutines eventually talk to an RDBMs instance, its disk I/O may quite easily serialize all those goroutines which will merely wait for their turn to have their data accepted. The bottleneck may be simpler—say, in each worker goroutine you carelessly execute some long-running operation while holding a lock contended on by all those goroutines; this obviously serializes them all.

The next step would be to actually measure (I mean, by writing a benchmark) how many time does it take for a single worker to complete its unit of work. Then you need to measure how this number changes when increasing the concurrency factor. After collecting these data, you will be able to do educated projections about at what realistic rate your system is able to handle the requests.

The next step is to think through your strategy at making your system fulfil those calculated expectations. Usually this means limiting the rate of ingress requests. There are different approaches to achieve this. Look at golang.org/x/time/rate for a time-based rate limiter but it's possible to start with lower-tech approaches such as using a buffered channel as a counting semaphore. The requests which would overflow your capacity may be rejected (typically with HTTP status code 429, see this). You might also consider queueing them briefly but I'd try this only to serve as a cherry on a pie—that is, when you have the rest sorted out completely.

The question of what to do with rejected requests depends on your setting. Typically you try to "scale horizontally" by deploying more than one service to process your requests and teach your clients to switch over available services. (I'd stress that it means several independent services—if they all share some target sink which collects their data, they might be limited by the ultimate capacity of that sink, and adding more systems won't gain you anything.)

Let me repeat that the general problem has no magic solutions: if your complete stystem (with this HTTP service you're writing being merely its front-end, gateway, part) is only able to handle N RPS of load, no amount of scattering go processRequest() is going to make it handle requests at a higher pace. The easy concurrency Go offers is not a silver bullet, it's a machine gun.