请教个upstream的问题

level077_0b9b

这个问题可能和nginx的关系不大，求教各位排查思路。

一台nginx做内部调用转发，后端是tomcat

在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。

在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？

猜测是不是网络方面的问题，如tomcat很快的结束了请求，但最终响应发出去延时了？

nginx version: nginx/1.5.8

built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)

configure arguments: --prefix=/usr/local/app/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../lua-nginx-module-0.9.5rc2 --add-module=../lua-upstream-nginx-module-master

tomcat version: Apache Tomcat/6.0.36, 使用的是httpnioprotocol。

nginx upstream相关配置片段：

keepalive_timeout 5;

log_format main '$remote_addr - $remote_port [$time_local] '

'"$request" $status $body_bytes_sent '

'"$http_referer" "$http_user_agent" '

'$http_host $upstream_addr $upstream_response_time $request_time';

upstream video {

server 192.168.0.202:8110;

server 192.168.0.202:8111;

server 192.168.0.202:8112;

server 192.168.0.77:8110;

server 192.168.0.77:8111;

server 192.168.0.77:8112;

server 192.168.0.86:8110;

server 192.168.0.86:8111;

server 192.168.0.86:8112;

keepalive 32;

}

server {

listen 8106;

server_name kas2video;

access_log /usr/local/app/nginx/logs/access.log main;

location / {

proxy_pass http://video;

proxy_http_version 1.1;

proxy_set_header Connection "";

}

agentzh

Hello!

2014-07-25 1:02 GMT-07:00 level077:
> 在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。
> 在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？
>

感觉确实有些 OT :)

我想到的一个建议是直接对你的 tomcat 服务进程响应较慢的请求的实际执行细节进行动态追踪（比如使用 systemtap 或者 dtrace）。

另一个建议是对你的 tomcat 进程分别绘出 on-CPU 和 off-CPU 火焰图进行宏观分析：

    https://github.com/openresty/nginx-systemtap-toolkit#sample-bt

    https://github.com/openresty/nginx-systemtap-toolkit#sample-bt-off-cpu

是的，这些工具可以用于 nginx 以外的进程。不过 tomcat 是纯 Java 编写的，JVM JIT 编译器生成的机器码会给
systemtap 默认的 stack unwinder 造成麻烦，不过网上看到有不少相关的支持，你可以 Google
一下，同时对这些工具进行修改。我对 Java 和 JVM 所知甚少，同时也兴趣不大。

Regards,
-agentzh

csulyj

这个问题解决了吗？

我现在遇到类似的问题，nginx + netty的http服务，nginx的request_time和upstream_response_time耗时都在1秒，但是后端netty耗时毫秒级，不知道从何入手排查。

在 2014年7月25日星期五 UTC+8下午4:02:07，level077写道：

这个问题可能和nginx的关系不大，求教各位排查思路。

一台nginx做内部调用转发，后端是tomcat

在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。
在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？

猜测是不是网络方面的问题，如tomcat很快的结束了请求，但最终响应发出去延时了？

nginx version: nginx/1.5.8
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)
configure arguments: --prefix=/usr/local/app/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../lua-nginx-module-0.9.5rc2 --add-module=../lua-upstream-nginx-module-master

tomcat version: Apache Tomcat/6.0.36, 使用的是httpnioprotocol。

nginx upstream相关配置片段：

keepalive_timeout 5;

log_format main '$remote_addr - $remote_port [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent" '
'$http_host $upstream_addr $upstream_response_time $request_time';

upstream video {
server 192.168.0.202:8110;
server 192.168.0.202:8111;
server 192.168.0.202:8112;
server 192.168.0.77:8110;
server 192.168.0.77:8111;
server 192.168.0.77:8112;
server 192.168.0.86:8110;
server 192.168.0.86:8111;
server 192.168.0.86:8112;
keepalive 32;
}

server {
listen 8106;
server_name kas2video;
access_log /usr/local/app/nginx/logs/access.log main;

location / {
proxy_pass http://video;
proxy_http_version 1.1;
proxy_set_header Connection "";
}
}


相关日志(去掉url)：
nginx：192.168.0.149 - 37373 [25/Jul/2014:15:27:37 +0800] "GET /xxxxxxx HTTP/1.1" 200 394 "-" "-" kas2video:8106 192.168.0.202:8110 0.649 0.649
tomcat： 192.168.0.63 - - [25/Jul/2014:15:27:36 +0800] GET /xxxxxxx HTTP/1.1 200 381 0.007

xuyz1988

nginx的upstream_response_time统计的是转发开始-收到响应总耗时，这包括网络延迟，netty耗时，业务耗时。netty打印的时间应该只是接收请求到处理完的时间。

这里的时间差主要体现网络抖动，netty接收请求时间。

当初遇到过同样问题，不过当时场景是nginx + tomcat和php

1.问题原因并发太高，大量请求在tomcat排队，所以应用看不到请求。

2.网络抖动厉害，这个可以抓包看看。我见过http拆包，http头信息和body延迟超过60s的。

发自网易邮箱大师

在2017年01月18日 23:28，yuanjun Li 写道：

这个问题解决了吗？

我现在遇到类似的问题，nginx + netty的http服务，nginx的request_time和upstream_response_time耗时都在1秒，但是后端netty耗时毫秒级，不知道从何入手排查。

在 2014年7月25日星期五 UTC+8下午4:02:07，level077写道：
这个问题可能和nginx的关系不大，求教各位排查思路。

一台nginx做内部调用转发，后端是tomcat

在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。
在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？

猜测是不是网络方面的问题，如tomcat很快的结束了请求，但最终响应发出去延时了？

nginx version: nginx/1.5.8
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)
configure arguments: --prefix=/usr/local/app/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../lua-nginx-module-0.9.5rc2 --add-module=../lua-upstream-nginx-module-master

tomcat version: Apache Tomcat/6.0.36, 使用的是httpnioprotocol。

nginx upstream相关配置片段：

keepalive_timeout 5;

log_format main '$remote_addr - $remote_port [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent" '
'$http_host $upstream_addr $upstream_response_time $request_time';

upstream video {
server 192.168.0.202:8110;
server 192.168.0.202:8111;
server 192.168.0.202:8112;
server 192.168.0.77:8110;
server 192.168.0.77:8111;
server 192.168.0.77:8112;
server 192.168.0.86:8110;
server 192.168.0.86:8111;
server 192.168.0.86:8112;
keepalive 32;
}

server {
listen 8106;
server_name kas2video;
access_log /usr/local/app/nginx/logs/access.log main;

location / {
proxy_pass http://video;
proxy_http_version 1.1;
proxy_set_header Connection "";
}
}


相关日志(去掉url)：
nginx：192.168.0.149 - 37373 [25/Jul/2014:15:27:37 +0800] "GET /xxxxxxx HTTP/1.1" 200 394 "-" "-" kas2video:8106 192.168.0.202:8110 0.649 0.649
tomcat： 192.168.0.63 - - [25/Jul/2014:15:27:36 +0800] GET /xxxxxxx HTTP/1.1 200 381 0.007

--

level077_0b9b

是的，目前看到的问题基本都是第一种情况。

还有种情况是nginx和tomcat之间使用长链，业务返回响应后还继续处理其他逻辑，如果后续请求还是通过这个连接发送到tomcat的话，tomcat是无法第一时间看到请求的，也会有同样的情况。

在 2017年1月21日星期六 UTC+8下午10:44:43，徐涛写道：

nginx的upstream_response_time统计的是转发开始-收到响应总耗时，这包括网络延迟，netty耗时，业务耗时。netty打印的时间应该只是接收请求到处理完的时间。
这里的时间差主要体现网络抖动，netty接收请求时间。

当初遇到过同样问题，不过当时场景是nginx + tomcat和php
1.问题原因并发太高，大量请求在tomcat排队，所以应用看不到请求。
2.网络抖动厉害，这个可以抓包看看。我见过http拆包，http头信息和body延迟超过60s的。

发自网易邮箱大师

在2017年01月18日 23:28，yuanjun Li 写道：
这个问题解决了吗？

我现在遇到类似的问题，nginx + netty的http服务，nginx的request_time和upstream_response_time耗时都在1秒，但是后端netty耗时毫秒级，不知道从何入手排查。

在 2014年7月25日星期五 UTC+8下午4:02:07，level077写道：
这个问题可能和nginx的关系不大，求教各位排查思路。

一台nginx做内部调用转发，后端是tomcat

在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。
在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？

猜测是不是网络方面的问题，如tomcat很快的结束了请求，但最终响应发出去延时了？

nginx version: nginx/1.5.8
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)
configure arguments: --prefix=/usr/local/app/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../lua-nginx-module-0.9.5rc2 --add-module=../lua-upstream-nginx-module-master

tomcat version: Apache Tomcat/6.0.36, 使用的是httpnioprotocol。

nginx upstream相关配置片段：

keepalive_timeout 5;

log_format main '$remote_addr - $remote_port [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent" '
'$http_host $upstream_addr $upstream_response_time $request_time';

upstream video {
server 192.168.0.202:8110;
server 192.168.0.202:8111;
server 192.168.0.202:8112;
server 192.168.0.77:8110;
server 192.168.0.77:8111;
server 192.168.0.77:8112;
server 192.168.0.86:8110;
server 192.168.0.86:8111;
server 192.168.0.86:8112;
keepalive 32;
}

server {
listen 8106;
server_name kas2video;
access_log /usr/local/app/nginx/logs/access.log main;

location / {
proxy_pass http://video;
proxy_http_version 1.1;
proxy_set_header Connection "";
}
}


相关日志(去掉url)：
nginx：192.168.0.149 - 37373 [25/Jul/2014:15:27:37 +0800] "GET /xxxxxxx HTTP/1.1" 200 394 "-" "-" kas2video:8106 192.168.0.202:8110 0.649 0.649
tomcat： 192.168.0.63 - - [25/Jul/2014:15:27:36 +0800] GET /xxxxxxx HTTP/1.1 200 381 0.007

--

csulyj

线上抓包的话，并发大的情况下，怎么能快速找出延迟大的包？

在 2017年1月21日下午10:44，徐涛 <xuy...@163.com>写道：

nginx的upstream_response_time统计的是转发开始-收到响应总耗时，这包括网络延迟，netty耗时，业务耗时。netty打印的时间应该只是接收请求到处理完的时间。
这里的时间差主要体现网络抖动，netty接收请求时间。

当初遇到过同样问题，不过当时场景是nginx + tomcat和php
1.问题原因并发太高，大量请求在tomcat排队，所以应用看不到请求。
2.网络抖动厉害，这个可以抓包看看。我见过http拆包，http头信息和body延迟超过60s的。

发自网易邮箱大师

在2017年01月18日 23:28，yuanjun Li 写道：
这个问题解决了吗？

我现在遇到类似的问题，nginx + netty的http服务，nginx的request_time和upstream_response_time耗时都在1秒，但是后端netty耗时毫秒级，不知道从何入手排查。

在 2014年7月25日星期五 UTC+8下午4:02:07，level077写道：
这个问题可能和nginx的关系不大，求教各位排查思路。

一台nginx做内部调用转发，后端是tomcat

在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。
在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？

猜测是不是网络方面的问题，如tomcat很快的结束了请求，但最终响应发出去延时了？

nginx version: nginx/1.5.8
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)
configure arguments: --prefix=/usr/local/app/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../lua-nginx-module-0.9.5rc2 --add-module=../lua-upstream-nginx-module-master

tomcat version: Apache Tomcat/6.0.36, 使用的是httpnioprotocol。

nginx upstream相关配置片段：

keepalive_timeout 5;

log_format main '$remote_addr - $remote_port [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent" '
'$http_host $upstream_addr $upstream_response_time $request_time';

upstream video {
server 192.168.0.202:8110;
server 192.168.0.202:8111;
server 192.168.0.202:8112;
server 192.168.0.77:8110;
server 192.168.0.77:8111;
server 192.168.0.77:8112;
server 192.168.0.86:8110;
server 192.168.0.86:8111;
server 192.168.0.86:8112;
keepalive 32;
}

server {
listen 8106;
server_name kas2video;
access_log /usr/local/app/nginx/logs/access.log main;

location / {
proxy_pass http://video;
proxy_http_version 1.1;
proxy_set_header Connection "";
}
}


相关日志(去掉url)：
nginx：192.168.0.149 - 37373 [25/Jul/2014:15:27:37 +0800] "GET /xxxxxxx HTTP/1.1" 200 394 "-" "-" kas2video:8106 192.168.0.202:8110 0.649 0.649
tomcat： 192.168.0.63 - - [25/Jul/2014:15:27:36 +0800] GET /xxxxxxx HTTP/1.1 200 381 0.007

--

--

csulyj

> 业务返回响应后还继续处理其他逻辑

其他逻辑是指nginx里面的逻辑，还是后端服务的逻辑？

在 2017年2月9日下午11:41，level077 <lev...@gmail.com>写道：

是的，目前看到的问题基本都是第一种情况。
还有种情况是nginx和tomcat之间使用长链，业务返回响应后还继续处理其他逻辑，如果后续请求还是通过这个连接发送到tomcat的话，tomcat是无法第一时间看到请求的，也会有同样的情况。

在 2017年1月21日星期六 UTC+8下午10:44:43，徐涛写道：

nginx的upstream_response_time统计的是转发开始-收到响应总耗时，这包括网络延迟，netty耗时，业务耗时。netty打印的时间应该只是接收请求到处理完的时间。
这里的时间差主要体现网络抖动，netty接收请求时间。

当初遇到过同样问题，不过当时场景是nginx + tomcat和php
1.问题原因并发太高，大量请求在tomcat排队，所以应用看不到请求。
2.网络抖动厉害，这个可以抓包看看。我见过http拆包，http头信息和body延迟超过60s的。

发自网易邮箱大师

在2017年01月18日 23:28，yuanjun Li 写道：
这个问题解决了吗？

我现在遇到类似的问题，nginx + netty的http服务，nginx的request_time和upstream_response_time耗时都在1秒，但是后端netty耗时毫秒级，不知道从何入手排查。

在 2014年7月25日星期五 UTC+8下午4:02:07，level077写道：
这个问题可能和nginx的关系不大，求教各位排查思路。

一台nginx做内部调用转发，后端是tomcat

在nginx日志里偶尔会发现响应时间比较长的请求，如大于0.5秒，但是在后端的日志里看到的响应时间可能只有50ms。
在这两台机器上抓包，看到nginx是第一时间将包发给后端了（之前有看到nginx，在接受到请求后，并没有第一时间发送给后端，设置net.ipv4.tcp_tw_reuse=0后，貌似没再出现这个问题），tomcat也是第一时间收到了请求，但是响应确实是在很长时间后发出来的，难道是tomcat日志记录的响应时间不准？

猜测是不是网络方面的问题，如tomcat很快的结束了请求，但最终响应发出去延时了？

nginx version: nginx/1.5.8
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-3) (GCC)
configure arguments: --prefix=/usr/local/app/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../lua-nginx-module-0.9.5rc2 --add-module=../lua-upstream-nginx-module-master

tomcat version: Apache Tomcat/6.0.36, 使用的是httpnioprotocol。

nginx upstream相关配置片段：

keepalive_timeout 5;

log_format main '$remote_addr - $remote_port [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent" '
'$http_host $upstream_addr $upstream_response_time $request_time';

upstream video {
server 192.168.0.202:8110;
server 192.168.0.202:8111;
server 192.168.0.202:8112;
server 192.168.0.77:8110;
server 192.168.0.77:8111;
server 192.168.0.77:8112;
server 192.168.0.86:8110;
server 192.168.0.86:8111;
server 192.168.0.86:8112;
keepalive 32;
}

server {
listen 8106;
server_name kas2video;
access_log /usr/local/app/nginx/logs/access.log main;

location / {
proxy_pass http://video;
proxy_http_version 1.1;
proxy_set_header Connection "";
}
}


相关日志(去掉url)：
nginx：192.168.0.149 - 37373 [25/Jul/2014:15:27:37 +0800] "GET /xxxxxxx HTTP/1.1" 200 394 "-" "-" kas2video:8106 192.168.0.202:8110 0.649 0.649
tomcat： 192.168.0.63 - - [25/Jul/2014:15:27:36 +0800] GET /xxxxxxx HTTP/1.1 200 381 0.007

--

--