why nginx request time too big while upstream response time small

[白庆奇]

Hi,
I'm using nginx as a reverse proxy to my backends. I see sometimes the
request time is too big while the upstream response time is quite
small:

211.139.145.99 - - [26/Oct/2012:10:49:55 +0800] 5.287 "POST
/service/3/app_components/?screen_type=iphone_2x&device_platform=iphone&channel=App%20Store&app_name=news_article&device_type=iPhone%205&os_version=6.0&version_code=1.2&uuid=27506e0c4c09b881f44e1a458f471f3de165cc34
HTTP/1.1" 200 6916 "-" "-" "i.snssdk.com"
"uuid=27506e0c4c09b881f44e1a458f471f3de165cc34"
upstream_response_time: 0.287

As I analyze the access log, I see sometimes there are many logs like
above which the request time is 5 or more bigger than upstream
response time.

For find out the big difference between the request time and request
respons time, i use tcpdump to get packages on nginx server 80 port
like :

As I analyze the packages， I find many Strange phenomenon below:

219.234.82.78 - - [26/Oct/2012:10:52:48 +0800] 5.260 "POST
/service/2/app_alert/?uuid=4960614f474b0990f3dcb83c12bde42e55eb42b1&lang=zh-Hans&access=mobile&carrier=%E4%B8%AD%E5%9B%BD%E7%A7%BB%E5%8A%A8&mcc_mnc=46002&device_platform=iphone&channel=App%20Store&app_name=joke_essay&device_type=iPhone%204&os_version=6.0&version_code=1.3
HTTP/1.1" 200 49 "-" "\xE5\x86\x85\xE6\xB6\xB5\xE6\xAE\xB5\xE5\xAD\x90
1.3 (iPhone; iPhone OS 6.0; zh_CN)" "i.snssdk.com"
"uuid=4960614f474b0990f3dcb83c12bde42e55eb42b1"
upstream_response_time: 0.260

tcpdump:

10:52:43.099494 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [S],
seq 599253512, win 5840, options [mss 1460], length 0
10:52:43.099526 IP 60.29.255.91.80 > 219.234.82.78.57120: Flags [S.],
seq 1300382255, ack 599253513, win 14600, options [mss 1460], length 0
10:52:43.110052 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [.],
ack 1, win 5840, length 0
10:52:43.614325 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [P.],
seq 1:553, ack 1, win 5840, length 552
E..P.. at .1.....RN<..[. .P#.. M.B0P.......POST
/service/2/app_alert/?uuid=4960614f474b0990f3dcb83c12bde42e55eb42b1&lang=zh-Hans&access=mobile&carrier=%E4%B8%AD%E5%9B%BD%E7%A7%BB%E5%8A%A8&mcc_mnc=46002&device_platform=iphone&channel=App%20Store&app_name=joke_essay&device_type=iPhone%204&os_version=6.0&version_code=1.3
HTTP/1.1^M
Host: i.snssdk.com^M
Accept-Encoding: gzip^M
Content-Length: 0^M
Cookie: uuid=4960614f474b0990f3dcb83c12bde42e55eb42b1^M
User-Agent: ............ 1.3 (iPhone; iPhone OS 6.0; zh_CN)^M
Via: 1.1 dxt_2_168 (squid/3.1.16)^M
Cache-Control: max-age=0^M
Connection: keep-alive^M

10:52:46.613596 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [P.],
seq 1:553, ack 1, win 5840, length 552
10:52:52.614245 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [P.],
seq 1:553, ack 1, win 5840, length 552
10:53:03.048953 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [F.],
seq 553, ack 1, win 5840, length 0
10:53:28.987395 IP 60.29.255.91.80 > 219.234.82.78.57120: Flags [P.],
seq 1:229, ack 554, win 15456, length 228

10:53:28.997888 IP 219.234.82.78.57120 > 60.29.255.91.80: Flags [R],
seq 599254066, win 0, length 0

I analyze many nginx access log with tcpdump packages. I find
sometimes the nginx server does not response ack on the client in
time, when the client post request to server, and in some cases the
server does not send any package more after The three handshake with
client.

I fell quite puzzled why nginx log the request time 5.260 seconds
while the nginx server send the ack package 40 seconds later.

And I try debug the nginx, I find the request time logged after the
ngx_http_finalize_request, which call the sendfile to write the
reseult the tcp sk_buffer.

I guess there is some thing wrong with my system or network, but i use

netstat -s -t, i find no packages dropped outgoing:

    2922 ICMP packets dropped because they were out-of-window
    73 ICMP packets dropped because socket was locked
    927337 SYNs to LISTEN sockets dropped

Any idea what's happening and how to resolve this problem ?

Thanks.


-- 
thanks
rockybai
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20121028/440484ba/attachment.html>