Major slowness in 1% of nginx responses under load

Question

Ubuntu 14.04

apt-get install nginx apache2-utils

Then vi /etc/nginx/sites-enabled/default to these contents:

server {
  listen 80 default_server;

  location / {
    return 200 "Ok";
  }
}

service nginx restart

Running:

ab -c 500 -k -n 100000 127.0.0.1/

I get the result:

Percentage of the requests served within a certain time (ms)
  50%      0
  66%      0
  75%      0
  80%      0
  90%      0
  95%      0
  98%     14
  99%    489
 100%   3065 (longest request)

Ok, so I get most of the responses very fast (which is to be expected), but about 1% (nearly 1000 requests) of responses are very slow. (0.5s - 3s)

Why is this happening? How to find the source of problem? I guessing kernel/sysctl, but how to find out exactly what's up?

---

UPDATE1

I tried to replace ab with siege and result is the same.

siege -c 500 -r 200 -b 127.0.0.1/

....
Concurrency:              240.67
Successful transactions:      100000
Failed transactions:               0
Longest transaction:            1.50
Shortest transaction:           0.00

I tried changing some variables in nginx and restarting server after each change and re-running ab.

worker_processes 10;

worker_connections 7680;

multi_accept on;

events { use select; }

events { use poll; }

events { use epoll; }

I tried adjusting sysctl and re-running test each time:

net.core.somaxconn=5120 # including listen directive backlog in nginx

net.core.netdev_max_backlog=5120

I raised number of open files to 5000000 and re-run test.

I tried some other tcp congestion control methods and re-run the test each time.

sysctl -w net.ipv4.tcp_congestion_control=hybla

sysctl -w net.ipv4.tcp_congestion_control=illinois

sysctl -w net.ipv4.tcp_congestion_control=lp

sysctl -w net.ipv4.tcp_congestion_control=probe

sysctl -w net.ipv4.tcp_congestion_control=scalable

sysctl -w net.ipv4.tcp_congestion_control=vegas

sysctl -w net.ipv4.tcp_congestion_control=veno

sysctl -w net.ipv4.tcp_congestion_control=westwood

sysctl -w net.ipv4.tcp_congestion_control=yeah

I tried more sysctl vars and re-run the test each time.

sysctl -w net.core.rmem_max=67108864 

sysctl -w net.ipv4.tcp_rmem='4096 87380 33554432'

sysctl -w net.ipv4.tcp_wmem='4096 65536 33554432'

sysctl -w net.core.netdev_max_backlog=30000

sysctl -w net.ipv4.tcp_congestion_control=htcp

sysctl -w net.ipv4.tcp_mtu_probing=1

sysctl -w net.core.rmem_max=134217728 

sysctl -w net.core.wmem_max=134217728 

sysctl -w net.ipv4.tcp_rmem='4096 87380 67108864'

sysctl -w net.ipv4.tcp_wmem='4096 65536 67108864'

sysctl -w net.core.netdev_max_backlog=250000

sysctl -w net.ipv4.tcp_congestion_control=htcp

sysctl -w net.ipv4.tcp_mtu_probing=1

Finally, I downloaded golang and compiled the server and tested ab against this basic server - everything is the same.

package main

import (
    "fmt"
    "net/http"
)

func handler(w http.ResponseWriter, r *http.Request) {
    fmt.Fprintf(w, "OK")
}

func main() {
    http.HandleFunc("/", handler)
    http.ListenAndServe(":8080", nil)
}

go run test.go

Nothing seems to affect this 1%.

UPDATE2

Ok, this might have something to do with CPU saturation. On 16-core GCE machine the effect is much better and less noticeable. The original test was done on 1-core Digital Ocean instance.

UPDATE3

Yep, has to be something with CPU. No effect on 4-core GCE. (Added as answer)

Answer 1

It seems the answer is - not enough CPU

4-core GCE

  Percentage of the requests served within a certain time (ms)
    50%      8
    66%     12
    75%     16
    80%     17
    90%     24
    95%     28
    98%     35
    99%     41
   100%     63 (longest request)

1-core GCE

Percentage of the requests served within a certain time (ms)
  50%      0
  66%      0
  75%      0
  80%      0
  90%      0
  95%      0
  98%      4
  99%    509
 100%   3597 (longest request)