title: Go HTTP Server Performance Issue
body: <p>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. </p>
  
  <p>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. </p>
  
  <p>Could anyone please help me with some ideas on what the reason could be so that I can explore more.</p>
  
  <pre><code>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(&amp;event)
          if err != nil {
              http.Error(w, "Invalid json: " + err.Error(), http.StatusBadRequest)
              return
          }
          go service.Collect(&amp;event)
          w.Write([]byte("Accepted"))
          stats.Timing("HttpResponseDuration", time.Since(startTime), nil, 1)
      }
  
      return http.HandlerFunc(handleFunc)
  }
  </code></pre>
  
  <p>I ran a test with 1000 requests per second and profiled it. Following are the results.</p>
  
  <pre><code>(pprof) top20
  Showing nodes accounting for 3.97s, 90.85% of 4.37s total
  Dropped 89 nodes (cum &lt;= 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 &lt;= 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) 
  </code></pre>