# Why nginx request time too big while upstream response time small

**URL:** <https://www.ruby-forum.com/t/why-nginx-request-time-too-big-while-upstream-response-time-small/224053>\
**Category:** NGINX\
**Created:** [October 28, 2012, 10:47am UTC](https://www.ruby-forum.com/t/why-nginx-request-time-too-big-while-upstream-response-time-small/224053 "2012-10-28T10:47:11Z")\
**Posts on this page:** 1\
**Page:** 1

<div class="post-metadata">

**Author:** ![aris](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/a/258eb7/32.png) [@aris](https://www.ruby-forum.com/u/aris)\
**Post date:** [October 28, 2012, 10:47am UTC](https://www.ruby-forum.com/t/why-nginx-request-time-too-big-while-upstream-response-time-small/224053/1 "2012-10-28T10:47:11Z")

</div>

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](http://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](http://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  
removed\_email\_address@domain.invalid\<…[. .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.