Welcome! Log In Create A New Profile

Advanced

[newbie] nginx extremely slow(1 reqs/sec) when serving static files

Posted by aqingsir 
[newbie] nginx extremely slow(1 reqs/sec) when serving static files
January 16, 2016 11:35AM
Hi,
there.

I use nginx to serve static files and django(gunicorn), which turns out to be extremely slow (~1 requests/second, cannot believe it) even for static files. I've tried almost all methods I could find, including: disable iptables; disable gunicorn; add file cache; increate worker_rlimit_nofile, disable access lo, but performance does not improve.

As the throughput is so slow, I believe it should be a silly problem, but I could not figure it out after fighting for over 1 days. So any help or suggestion is highly appreciated.

A. Here is the basic environment of my server:
A1.ping
PING myserver.com (182.92.**.**): 56 data bytes
64 bytes from 182.92.**.**: icmp_seq=0 ttl=42 time=7.652 ms

A2. top
top - 00:28:52 up 1:08, 2 users, load average: 0.03, 0.03, 0.05
Tasks: 115 total, 1 running, 114 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.7 us, 0.2 sy, 0.0 ni, 99.0 id, 0.2 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1882832 total, 1383480 free, 163208 used, 336144 buff/cache
KiB Swap: 2097148 total, 2097148 free, 0 used. 1577200 avail Mem

A3. ulimit -n
65535
cat /proc/sys/fs/file-max
185146
cat /proc/sys/fs/file-nr
1024 0 185146
less /etc/sysctl.conf
net.ipv4.tcp_max_syn_backlog = 32768
net.ipv4.tcp_synack_retries = 2
net.ipv4.ip_local_port_range = 10000 65000
net.core.somaxconn = 32768
net.core.netdev_max_backlog = 32768
net.ipv4.tcp_max_orphans = 32768
...

A4. iptables // even if I disable iptables, throughput did not increate
sudo iptables -L -n
Chain INPUT (policy ACCEPT)
target prot opt source destination
ACCEPT tcp -- 127.0.0.1 127.0.0.1 tcp dpt:3306
ACCEPT tcp -- 0.0.0.0/0 0.0.0.0/0 tcp dpt:1234 state NEW,ESTABLISHED
ACCEPT tcp -- 0.0.0.0/0 0.0.0.0/0 tcp dpt:80 state NEW,ESTABLISHED

Chain FORWARD (policy ACCEPT)
target prot opt source destination

Chain OUTPUT (policy ACCEPT)
target prot opt source destination
ACCEPT tcp -- 0.0.0.0/0 0.0.0.0/0 tcp spt:1234 state ESTABLISHED
ACCEPT tcp -- 0.0.0.0/0 0.0.0.0/0 tcp spt:80 state ESTABLISHED

A5. nginx.conf
user nginx;
worker_processes auto; // with 2 cpu cores
worker_cpu_affinity 01 10;
error_log /var/log/nginx/error.log;
pid /var/run/nginx.pid;
worker_rlimit_nofile 65535;

events {
worker_connections 16384;
use epoll;
multi_accept on;
}

http {
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent ($request_time-$upstream_response_time) "$http_referer" '
'"$http_user_agent" "$http_x_forwarded_for"';

access_log /var/log/nginx/access.log main;

server_tokens off;
sendfile on;
tcp_nopush on;
tcp_nodelay on;
types_hash_max_size 2048;

open_file_cache max=65535 inactive=5m;
open_file_cache_valid 60s;
open_file_cache_min_uses 2;
open_file_cache_errors on;

include /etc/nginx/mime.types;
default_type application/octet-stream;

include /etc/nginx/conf.d/*.conf; // where contains gzip.conf
include /etc/nginx/servers/*.conf; // where contains server.conf
}

A6. server.conf
server {
listen 80 default backlog=8192;
server_name myhost.com;
root /www/myhost/latest;
access_log /var/log/nginx/myhost.log main;

location / {
proxy_pass http://0.0.0.0:8000;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header HOST $http_host;
proxy_set_header X-NginX-Proxy true;
proxy_redirect off;
}

location ~ /images {
if ($http_origin ~ "myhost.com$") {
add_header "Access-Control-Allow-Origin" $http_origin;
add_header 'Access-Control-Allow-Methods' 'GET';
}
root /storage;
expires max;
}

location ~ /.ht {
deny all;
}
}

B. When I run AB tests with 2 or 50 concurrencies, the performance is poor:
ab -s 30000 -n 50 -c 50 http://myserver.com/images/test.jpg

Requests per second: 0.97 [#/sec] (mean)
Transfer rate: 174.02 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 5 9 6.4 8 70
Processing: 8219 23303 10201.3 22035 73695
Waiting: 7 794 2325.1 76 13760
Total: 8227 23311 10200.9 22044 73700

B1. netstat -an|awk '/^tcp/{++S[$NF]}END{for (a in S)print a,S[a]}'
LISTEN 4
SYN_RECV 1
ESTABLISHED 67 // changes over time, but TIME_WAIT has a maximum value of 1 or 2;

B2. top
nginx is fine with memory or CPU usage

B3. if I enable static_status module, it also seems fine:
Active connections: 55
server accepts handled requests
164 164 235
Reading: 0 Writing: 40 Waiting: 15 // changes over time

C. Useful information I could find:

C1. access log files:
117.114.129.170 - - [16/Jan/2016:23:24:29 +0800] "GET /images/test.jpg HTTP/1.0" 200 219868 (37.269--) "-" "ApacheBench/2.3" "-"
Where 37.269 is $request_time as configured above;
From B1 I'm sure that all connections are connected(not in TIME_WAIT state), so it seems to be nginx

C2. I enable debug level for error logs:
There seems to be a lot of "Resource temporarily unavailable" errors.

2016/01/16 23:47:51 [debug] 1270#0: accept() not ready (11: Resource temporarily unavailable)
2016/01/16 23:47:51 [debug] 1270#0: *468 recv() not ready (11: Resource temporarily unavailable)

C3. And here is a typical log for a request, which I understand little:
2016/01/16 21:42:01 [debug] 15027#0: *907 accept: 117.114.**.** fd:21
2016/01/16 21:42:01 [debug] 15027#0: posix_memalign: 00007F7B51D3A9C0:256 @16
2016/01/16 21:42:01 [debug] 15027#0: *907 event timer add: 21: 60000:1452951781579
2016/01/16 21:42:01 [debug] 15027#0: *907 reusable connection: 1
2016/01/16 21:42:01 [debug] 15027#0: *907 epoll add event: fd:21 op:1 ev:80002001
2016/01/16 21:42:01 [debug] 15027#0: accept() not ready (11: Resource temporarily unavailable)
2016/01/16 21:42:01 [debug] 15027#0: worker cycle
2016/01/16 21:42:01 [debug] 15027#0: accept mutex locked
2016/01/16 21:42:01 [debug] 15027#0: epoll timer: 44947
2016/01/16 21:42:01 [debug] 15027#0: epoll: fd:21 ev:0001 d:00007F7B48FF1880
2016/01/16 21:42:01 [debug] 15027#0: *907 post event 00007F7B4FE4A420
2016/01/16 21:42:01 [debug] 15027#0: *907 delete posted event 00007F7B4FE4A420
2016/01/16 21:42:01 [debug] 15027#0: *907 http wait request handler
2016/01/16 21:42:01 [debug] 15027#0: *907 malloc: 00007F7B51DDC200:1024
2016/01/16 21:42:01 [debug] 15027#0: *907 recv: fd:21 104 of 1024
2016/01/16 21:42:01 [debug] 15027#0: *907 reusable connection: 0
2016/01/16 21:42:01 [debug] 15027#0: *907 posix_memalign: 00007F7B51DC2520:4096 @16
2016/01/16 21:42:01 [debug] 15027#0: *907 http process request line
2016/01/16 21:42:01 [debug] 15027#0: *907 http request line: "GET /images/test.jpg HTTP/1.0"
2016/01/16 21:42:01 [debug] 15027#0: *907 http uri: "/images/test.jpg"
2016/01/16 21:42:01 [debug] 15027#0: *907 http args: ""
2016/01/16 21:42:01 [debug] 15027#0: *907 http exten: "jpg"
2016/01/16 21:42:01 [debug] 15027#0: *907 http process request header line
2016/01/16 21:42:01 [debug] 15027#0: *907 http header: "Host: static.tongshijia.com"
2016/01/16 21:42:01 [debug] 15027#0: *907 http header: "User-Agent: ApacheBench/2.3"
2016/01/16 21:42:01 [debug] 15027#0: *907 http header: "Accept: */*"
2016/01/16 21:42:01 [debug] 15027#0: *907 http header done
2016/01/16 21:42:01 [debug] 15027#0: *907 event timer del: 21: 1452951781579
2016/01/16 21:42:01 [debug] 15027#0: *907 generic phase: 0
2016/01/16 21:42:01 [debug] 15027#0: *907 rewrite phase: 1
2016/01/16 21:42:01 [debug] 15027#0: *907 test location: "/"
2016/01/16 21:42:01 [debug] 15027#0: *907 test location: "50x.html"
2016/01/16 21:42:01 [debug] 15027#0: *907 test location: ~ "/static/imager"
2016/01/16 21:42:01 [debug] 15027#0: *907 test location: ~ "/static"
2016/01/16 21:42:01 [debug] 15027#0: *907 test location: ~ "/images"
2016/01/16 21:42:01 [debug] 15027#0: *907 using configuration "/images"
2016/01/16 21:42:01 [debug] 15027#0: *907 http cl:-1 max:1048576
2016/01/16 21:42:01 [debug] 15027#0: *907 rewrite phase: 3
2016/01/16 21:42:01 [debug] 15027#0: *907 posix_memalign: 00007F7B51DE08E0:4096 @16
2016/01/16 21:42:01 [debug] 15027#0: *907 http script var
2016/01/16 21:42:01 [debug] 15027#0: *907 http script regex: "tongshijia.com$"
2016/01/16 21:42:01 [notice] 15027#0: *907 "tongshijia.com$" does not match "", client: 117.114.129.170, server: static.tongshijia.com, request: "GET /images/test.jpg HTTP/1.0", host: "static.tongshijia.com"
2016/01/16 21:42:01 [debug] 15027#0: *907 http script if
2016/01/16 21:42:01 [debug] 15027#0: *907 http script if: false
2016/01/16 21:42:01 [debug] 15027#0: *907 post rewrite phase: 4
2016/01/16 21:42:01 [debug] 15027#0: *907 generic phase: 5
2016/01/16 21:42:01 [debug] 15027#0: *907 generic phase: 6
2016/01/16 21:42:01 [debug] 15027#0: *907 generic phase: 7
2016/01/16 21:42:01 [debug] 15027#0: *907 generic phase: 8
2016/01/16 21:42:01 [debug] 15027#0: *907 access phase: 9
2016/01/16 21:42:01 [debug] 15027#0: *907 access phase: 10
2016/01/16 21:42:01 [debug] 15027#0: *907 post access phase: 11
2016/01/16 21:42:01 [debug] 15027#0: *907 content phase: 12
2016/01/16 21:42:01 [debug] 15027#0: *907 content phase: 13
2016/01/16 21:42:01 [debug] 15027#0: *907 content phase: 14
2016/01/16 21:42:01 [debug] 15027#0: *907 content phase: 15
2016/01/16 21:42:01 [debug] 15027#0: *907 content phase: 16
2016/01/16 21:42:01 [debug] 15027#0: *907 content phase: 17
2016/01/16 21:42:01 [debug] 15027#0: *907 http filename: "/storage/images/test.jpg"
2016/01/16 21:42:01 [debug] 15027#0: *907 add cleanup: 00007F7B51DC34F8
2016/01/16 21:42:01 [debug] 15027#0: *907 cached open file: /storage/images/test.jpg, fd:18, c:5, e:0, u:5
2016/01/16 21:42:01 [debug] 15027#0: *907 http static fd: 18
2016/01/16 21:42:01 [debug] 15027#0: *907 http set discard body
2016/01/16 21:42:01 [debug] 15027#0: *907 xslt filter header
2016/01/16 21:42:01 [debug] 15027#0: *907 HTTP/1.1 200 OK
Server: nginx
.........
2016/01/16 21:42:01 [debug] 15027#0: *907 write new buf t:1 f:0 00007F7B51DE0BC8, pos 00007F7B51DE0BC8, size: 329 file: 0, size: 0
2016/01/16 21:42:01 [debug] 15027#0: *907 http write filter: l:0 f:0 s:329
2016/01/16 21:42:01 [debug] 15027#0: *907 http output filter "/images/test.jpg?"
2016/01/16 21:42:01 [debug] 15027#0: *907 http copy filter: "/images/test.jpg?"
2016/01/16 21:42:01 [debug] 15027#0: *907 image filter
2016/01/16 21:42:01 [debug] 15027#0: *907 xslt filter body
2016/01/16 21:42:01 [debug] 15027#0: *907 http postpone filter "/images/test.jpg?" 00007FFF6F320C20
2016/01/16 21:42:01 [debug] 15027#0: *907 write old buf t:1 f:0 00007F7B51DE0BC8, pos 00007F7B51DE0BC8, size: 329 file: 0, size: 0
2016/01/16 21:42:01 [debug] 15027#0: *907 write new buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 219868
2016/01/16 21:42:01 [debug] 15027#0: *907 http write filter: l:1 f:0 s:220197
2016/01/16 21:42:01 [debug] 15027#0: *907 http write filter limit 0
2016/01/16 21:42:01 [debug] 15027#0: *907 tcp_nopush
2016/01/16 21:42:01 [debug] 15027#0: *907 writev: 329
2016/01/16 21:42:01 [debug] 15027#0: *907 sendfile: @0 219868
2016/01/16 21:42:01 [debug] 15027#0: *907 sendfile: 16807, @0 16807:219868
2016/01/16 21:42:01 [debug] 15027#0: *907 http write filter 00007F7B51DE0DA0
2016/01/16 21:42:01 [debug] 15027#0: *907 http copy filter: -2 "/images/test.jpg?"
2016/01/16 21:42:01 [debug] 15027#0: *907 http finalize request: -2, "/images/test.jpg?" a:1, c:1

Feel free to tell me if more information needed, and again thanks a lot for any help/suggestions.

regards,
aqingsir
Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 244
Record Number of Users: 8 on April 13, 2023
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready