Nginx-ru mailing list archive (nginx-ru@sysoev.ru)
Date Prev ][Date Next ][Thread Prev ][Thread Next ][Date Index ][Thread Index ]
POST: 2 seconds delay
To : <nginx-ru@xxxxxxxxx > Subject : POST: 2 seconds delay From : "Alexander Azarov" <azarov@xxxxxx > Date: Thu, 12 Oct 2006 19:56:02 +0400
Thread-index: AcbuFupTHf7DtaBwStOwTEvypBq+dw==
День добрый!
Время выполнения запроса POST почему-то 2 секунды, хотя напрямую на бэкенд в
районе 0.04 сек. В чем собака порылась? -- приложен кусок конфигурации и
debug log соединения (в нем видно, что задержка 2 секунды появляется
фрагментарно после посылки заголовков -- что-то с телом запроса?)
Linux srv1 2.6.16.13-vs2.0.2-rc19 #1 SMP PREEMPT Wed Jul 5 21:28:41 MSD 2006
i686 GNU/Linux
Александр.
2006/10/12 12:18:27 [debug] 6890#0: *1 accept: 192.168.80.83 fd:15
2006/10/12 12:18:27 [debug] 6890#0: *1 event timer add: 15: 60000:1014397228
2006/10/12 12:18:27 [debug] 6890#0: *1 epoll add event: fd:15 op:1 ev:80000001
2006/10/12 12:18:27 [debug] 6890#0: *1 post event 0817E7D0
2006/10/12 12:18:27 [debug] 6890#0: *1 delete posted event 0817E7D0
2006/10/12 12:18:27 [debug] 6890#0: *1 malloc: 080D4280:648
2006/10/12 12:18:27 [debug] 6890#0: *1 malloc: 08198778:16384
2006/10/12 12:18:27 [debug] 6890#0: *1 malloc: 080CE2E0:4096
2006/10/12 12:18:27 [debug] 6890#0: *1 http process request line
2006/10/12 12:18:27 [debug] 6890#0: *1 recv: fd:15 205 of 16384
2006/10/12 12:18:27 [debug] 6890#0: *1 http request line: "POST /_rules/445
HTTP/1.1"
2006/10/12 12:18:27 [debug] 6890#0: *1 http uri: "/_rules/445"
2006/10/12 12:18:27 [debug] 6890#0: *1 http args: ""
2006/10/12 12:18:27 [debug] 6890#0: *1 http exten: ""
2006/10/12 12:18:27 [debug] 6890#0: *1 http process request header line
2006/10/12 12:18:27 [debug] 6890#0: *1 http header: "User-Agent:
PECL::HTTP/1.3.2 (PHP/5.1.6-4)"
2006/10/12 12:18:27 [debug] 6890#0: *1 http header: "Host: alpha.company.local"
2006/10/12 12:18:27 [debug] 6890#0: *1 http header: "Accept: */*"
2006/10/12 12:18:27 [debug] 6890#0: *1 http header: "Content-Length: 2223"
2006/10/12 12:18:27 [debug] 6890#0: *1 http header: "Content-Type:
application/x-www-form-urlencoded"
2006/10/12 12:18:27 [debug] 6890#0: *1 http header: "Expect: 100-continue"
2006/10/12 12:18:27 [debug] 6890#0: *1 http header done
2006/10/12 12:18:27 [debug] 6890#0: *1 event timer del: 15: 1014397228
2006/10/12 12:18:27 [debug] 6890#0: *1 generic phase: 0
2006/10/12 12:18:27 [debug] 6890#0: *1 http script value:
"/home/company/contentserver"
2006/10/12 12:18:27 [debug] 6890#0: *1 http script set var
2006/10/12 12:18:27 [debug] 6890#0: *1 http script value: ""
2006/10/12 12:18:27 [debug] 6890#0: *1 http script set var
2006/10/12 12:18:27 [debug] 6890#0: *1 find location for "/_rules/445"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/_direct/content"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/_err"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/_inf"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/_log"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/_rules"
2006/10/12 12:18:27 [debug] 6890#0: *1 find location: "/_status"
2006/10/12 12:18:27 [debug] 6890#0: *1 using configuration "/_rules"
2006/10/12 12:18:27 [debug] 6890#0: *1 http cl:2223 max:1048576
2006/10/12 12:18:27 [debug] 6890#0: *1 generic phase: 2
2006/10/12 12:18:27 [debug] 6890#0: *1 http script regex: "^/_rules(.*)$"
2006/10/12 12:18:27 [debug] 6890#0: *1 http script capture: "/rules/445"
2006/10/12 12:18:27 [debug] 6890#0: *1 http script regex end
2006/10/12 12:18:27 [debug] 6890#0: *1 post rewrite phase: 3
2006/10/12 12:18:27 [debug] 6890#0: *1 access phase: 4
2006/10/12 12:18:27 [debug] 6890#0: *1 access phase: 5
2006/10/12 12:18:27 [debug] 6890#0: *1 post access phase: 6
2006/10/12 12:18:27 [debug] 6890#0: *1 malloc: 080CF2E8:4096
2006/10/12 12:18:27 [debug] 6890#0: *1 http read client request body
2006/10/12 12:18:27 [debug] 6890#0: *1 recv: fd:15 -1 of 2223
2006/10/12 12:18:27 [debug] 6890#0: *1 recv() not ready (11: Resource
temporarily unavailable)
2006/10/12 12:18:27 [debug] 6890#0: *1 http client request body recv -2
2006/10/12 12:18:27 [debug] 6890#0: *1 http client request body rest 2223
2006/10/12 12:18:27 [debug] 6890#0: *1 event timer add: 15: 60000:1014397228
2006/10/12 12:18:29 [debug] 6890#0: *1 post event 0817E7D0
2006/10/12 12:18:29 [debug] 6890#0: *1 delete posted event 0817E7D0
2006/10/12 12:18:29 [debug] 6890#0: *1 http read client request body
2006/10/12 12:18:29 [debug] 6890#0: *1 recv: fd:15 2223 of 2223
2006/10/12 12:18:29 [debug] 6890#0: *1 http client request body recv 2223
2006/10/12 12:18:29 [debug] 6890#0: *1 http client request body rest 0
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer del: 15: 1014397228
2006/10/12 12:18:29 [debug] 6890#0: *1 http init upstream, client timer: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 epoll add event: fd:15 op:3 ev:80000005
2006/10/12 12:18:29 [debug] 6890#0: *1 http proxy header: "User-Agent:
PECL::HTTP/1.3.2 (PHP/5.1.6-4)"
2006/10/12 12:18:29 [debug] 6890#0: *1 http proxy header: "Accept: */*"
2006/10/12 12:18:29 [debug] 6890#0: *1 http proxy header: "Content-Length: 2223"
2006/10/12 12:18:29 [debug] 6890#0: *1 http proxy header: "Content-Type:
application/x-www-form-urlencoded"
2006/10/12 12:18:29 [debug] 6890#0: *1 http proxy header: "Expect: 100-continue"
2006/10/12 12:18:29 [debug] 6890#0: *1 http proxy header:
"POST /rules/445 HTTP/1.0
Host: alpha.company.local
X-Real-IP: 192.168.80.83
X-Forwarded-For: 192.168.80.83
Connection: close
User-Agent: PECL::HTTP/1.3.2 (PHP/5.1.6-4)
Accept: */*
Content-Length: 2223
Content-Type: application/x-www-form-urlencoded
Expect: 100-continue
"
2006/10/12 12:18:29 [debug] 6890#0: *1 http cleanup add: 080CEDE4
2006/10/12 12:18:29 [debug] 6890#0: *1 socket 16
2006/10/12 12:18:29 [debug] 6890#0: *1 epoll add connection: fd:16 ev:80000005
2006/10/12 12:18:29 [debug] 6890#0: *1 connect to 192.168.80.118:8088, fd:16 #2
2006/10/12 12:18:29 [debug] 6890#0: *1 http upstream connect: -2
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer add: 16: 5000:1014344228
2006/10/12 12:18:29 [debug] 6890#0: *1 post event 0818B7D8
2006/10/12 12:18:29 [debug] 6890#0: *1 delete posted event 0818B7D8
2006/10/12 12:18:29 [debug] 6890#0: *1 http upstream check client, write
event:1, "/rules/445"
2006/10/12 12:18:29 [debug] 6890#0: *1 post event 0818B80C
2006/10/12 12:18:29 [debug] 6890#0: *1 delete posted event 0818B80C
2006/10/12 12:18:29 [debug] 6890#0: *1 http upstream send request handler
2006/10/12 12:18:29 [debug] 6890#0: *1 http upstream send request
2006/10/12 12:18:29 [debug] 6890#0: *1 chain writer buf size: 281
2006/10/12 12:18:29 [debug] 6890#0: *1 chain writer buf size: 2223
2006/10/12 12:18:29 [debug] 6890#0: *1 chain writer in: 080CEE00
2006/10/12 12:18:29 [debug] 6890#0: *1 writev: 2504
2006/10/12 12:18:29 [debug] 6890#0: *1 chain writer out: 00000000
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer del: 16: 1014344228
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer add: 16: 10000:1014349228
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter: l:0 f:0 s:225
2006/10/12 12:18:29 [debug] 6890#0: *1 tcp_nodelay
2006/10/12 12:18:29 [debug] 6890#0: *1 http upstream process non buffered
downstream
2006/10/12 12:18:29 [debug] 6890#0: *1 http output filter "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 copy filter: "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 http postpone filter "/rules/445?"
080CF0FC
2006/10/12 12:18:29 [debug] 6890#0: *1 http postpone filter out "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 http chunk: 349
2006/10/12 12:18:29 [debug] 6890#0: *1 write old buf t:1 f:0 080CF010, pos
080CF010, size: 225 file: 0, size: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 write new buf t:1 f:0 00000000, pos
080CF1AC, size: 5 file: 0, size: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 write new buf t:0 f:0 00000000, pos
080D03BB, size: 349 file: 0, size: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 write new buf t:0 f:0 00000000, pos
080A5DF1, size: 2 file: 0, size: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter: l:0 f:1 s:581
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter to send 0
2006/10/12 12:18:29 [debug] 6890#0: *1 writev: 581
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter 00000000
2006/10/12 12:18:29 [debug] 6890#0: *1 copy filter: 0 "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 recv: fd:16 0 of 4096
2006/10/12 12:18:29 [debug] 6890#0: *1 finalize http upstream request: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 finalize http proxy request
2006/10/12 12:18:29 [debug] 6890#0: *1 close http upstream connection: 16
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer del: 16: 1014349228
2006/10/12 12:18:29 [debug] 6890#0: *1 http output filter "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 copy filter: "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 http postpone filter "/rules/445?"
BFE42468
2006/10/12 12:18:29 [debug] 6890#0: *1 http postpone filter out "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 http chunk: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 write new buf t:0 f:0 00000000, pos
080A5DEE, size: 5 file: 0, size: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter: l:1 f:0 s:5
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter to send 0
2006/10/12 12:18:29 [debug] 6890#0: *1 writev: 5
2006/10/12 12:18:29 [debug] 6890#0: *1 http write filter 00000000
2006/10/12 12:18:29 [debug] 6890#0: *1 copy filter: 0 "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 http finalize request: 0, "/rules/445?"
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer add: 15: 5000:1014344232
2006/10/12 12:18:29 [debug] 6890#0: *1 http lingering close handler
2006/10/12 12:18:29 [debug] 6890#0: *1 recv: fd:15 -1 of 4096
2006/10/12 12:18:29 [debug] 6890#0: *1 recv() not ready (11: Resource
temporarily unavailable)
2006/10/12 12:18:29 [debug] 6890#0: *1 lingering read: -2
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer: 15, old: 1014344232, new:
1014344232
2006/10/12 12:18:29 [debug] 6890#0: *1 post event 0817E7D0
2006/10/12 12:18:29 [debug] 6890#0: *1 delete posted event 0817E7D0
2006/10/12 12:18:29 [debug] 6890#0: *1 http lingering close handler
2006/10/12 12:18:29 [debug] 6890#0: *1 recv: fd:15 0 of 4096
2006/10/12 12:18:29 [debug] 6890#0: *1 lingering read: 0
2006/10/12 12:18:29 [debug] 6890#0: *1 http close request
2006/10/12 12:18:29 [debug] 6890#0: *1 http log handler
2006/10/12 12:18:29 [debug] 6890#0: *1 free: 080D02F0
2006/10/12 12:18:29 [debug] 6890#0: *1 free: 080CE2E0, unused: 108
2006/10/12 12:18:29 [debug] 6890#0: *1 free: 080CF2E8, unused: 1841
2006/10/12 12:18:29 [debug] 6890#0: *1 close http connection: 15
2006/10/12 12:18:29 [debug] 6890#0: *1 event timer del: 15: 1014344232
2006/10/12 12:18:29 [debug] 6890#0: *1 free: 08198778
2006/10/12 12:18:29 [debug] 6890#0: *1 free: 080D4280
2006/10/12 12:18:29 [debug] 6890#0: *1 free: 080C8550, unused: 64
user www-data www-data;
worker_processes 6;
error_log /var/log/nginx/error.log notice;
#error_log /var/log/nginx/error.log debug;
pid /var/run/nginx.pid;
events {
worker_connections 1024;
}
....
sendfile on;
tcp_nopush on;
tcp_nodelay on;
client_header_timeout 1m;
client_body_timeout 1m;
send_timeout 2m;
keepalive_timeout 0;
gzip on;
gzip_min_length 6100;
client_header_buffer_size 16k;
large_client_header_buffers 4 64k;
client_body_temp_path /var/cache/nginx/client;
# Proxy defaults
proxy_buffering on;
proxy_temp_path /var/cache/nginx/proxy;
proxy_set_header Host $host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_intercept_errors on;
proxy_next_upstream error timeout invalid_header http_500 http_404;
proxy_connect_timeout 5s;
proxy_send_timeout 5s;
proxy_read_timeout 10s;
proxy_upstream_max_fails 1;
proxy_upstream_fail_timeout 30s;
....
location ^~ /_rules {
access_log /var/log/nginx/access.log combined buffer=64k;
rewrite ^/_rules(.*)$ /rules$1 break;
proxy_pass http://re.company.local:8080
