ngx.req.read_body()执行慢

jsonxt

Hi：

生产环境中，最近发现lua代码偶尔出现delay的情况。出现频率大约万分之一,有的时候会delay超过几十秒。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

通过增加打印日志，最后定位到引起delay的相关语句

ngx.log(ngx.INFO, "---1-----")

ngx.req.read_body()

ngx.log(ngx.INFO, "---2-----")

local post_args, err = ngx.req.get_post_args()

ngx.log(ngx.INFO, "---3-----")

jsonxt

我的理解是这样的。

ngx.req.read_body() 执行的时候，http请求的body数据没有全部到达，数据全部到达后，lua代码才继续执行

在 2016-05-13 15:46:28，"徐涛" <js...@163.com> 写道：

Hi：
生产环境中，最近发现lua代码偶尔出现delay的情况。出现频率大约万分之一,有的时候会delay超过几十秒。
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
通过增加打印日志，最后定位到引起delay的相关语句
ngx.log(ngx.INFO, "---1-----")
ngx.req.read_body()
ngx.log(ngx.INFO, "---2-----")
local post_args, err = ngx.req.get_post_args()
ngx.log(ngx.INFO, "---3-----")

相关日志
日志一(POST请求，ngx.var.request_length=998, 大约delay了40s)
2016/05/13 14:42:17 [info] 52172#0: *155912094 [lua] gateway.lua:98: get_all_args(): ---1-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"
2016/05/13 14:42:57 [info] 52172#0: *155912094 [lua] gateway.lua:101: get_all_args(): ---2-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"
2016/05/13 14:42:57 [info] 52172#0: *155912094 [lua] gateway.lua:103: get_all_args(): ---3-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"

日志一(POST请求，ngx.var.request_length=950, 大约delay了16s)
2016/05/13 14:35:47 [info] 51103#0: *155853488 [lua] gateway.lua:99: get_all_args(): ---1-----, client: 113.132.118.196, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "api.ffan.com"
2016/05/13 14:36:03 [info] 51103#0: *155853488 [lua] gateway.lua:103: get_all_args(): ---2-----, client: 113.132.118.196, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "api.ffan.com"

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

服务器配置：
32核cpu 128G内存 2个万兆网卡
nginx信息：
--prefix=/var/wd/gateway/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../echo-nginx-module-0.51 --add-module=../xss-nginx-module-0.04 --add-module=../ngx_coolkit-0.2rc1 --add-module=../set-misc-nginx-module-0.24 --add-module=../form-input-nginx-module-0.07 --add-module=../encrypted-session-nginx-module-0.03 --add-module=../srcache-nginx-module-0.25 --add-module=../ngx_lua-0.9.4 --add-module=../headers-more-nginx-module-0.25 --add-module=../array-var-nginx-module-0.03rc1 --add-module=../memc-nginx-module-0.14 --add-module=../redis2-nginx-module-0.10 --add-module=../redis-nginx-module-0.3.7 --add-module=../murmurhash-nginx-upstream-module-0.01 --add-module=../session-sticky-tengine-module-1.5.1 --add-module=../upstream-check-tengine-module-1.5.1 --add-module=../user_agent-tengine-module-1.5.1 --add-module=../nginx-delay-module-0.0.1 --add-module=../auth-request-nginx-module-0.2 --add-module=../rds-json-nginx-module-0.13 --add-module=../rds-csv-nginx-module-0.05 --with-ld-opt=-Wl,-rpath,/var/wd/gateway/luajit/lib --with-http_realip_module --with-http_stub_status_module --with-pcre=/root/gateway_ng/pcre-8.36 --with-http_spdy_module --with-http_addition_module --with-http_ssl_module

压力很低，大约 100tps
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

分析步骤
1.测试环境采用春哥开源的stap++中lj-lua-bt生成火焰图（附件 tmp.svg），个人能力不够，看不出问题.
2.生产环境关键点增加日志，最后确定产生delay的区域，如上面日志。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

问题：
1.什么因素会引起ngx.req.read_body()出现delay的情况
2.一般怎么根据火焰图分析问题

谢谢

--

scau.myzhan

16s，是不是客户端发生TCP重传了？

在 2016年5月13日星期五 UTC+8下午3:46:56，徐涛写道：

Hi：
生产环境中，最近发现lua代码偶尔出现delay的情况。出现频率大约万分之一,有的时候会delay超过几十秒。
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
通过增加打印日志，最后定位到引起delay的相关语句
ngx.log(ngx.INFO, "---1-----")
ngx.req.read_body()
ngx.log(ngx.INFO, "---2-----")
local post_args, err = ngx.req.get_post_args()
ngx.log(ngx.INFO, "---3-----")

相关日志
日志一(POST请求，ngx.var.request_length=998, 大约delay了40s)
2016/05/13 14:42:17 [info] 52172#0: *155912094 [lua] gateway.lua:98: get_all_args(): ---1-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"
2016/05/13 14:42:57 [info] 52172#0: *155912094 [lua] gateway.lua:101: get_all_args(): ---2-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"
2016/05/13 14:42:57 [info] 52172#0: *155912094 [lua] gateway.lua:103: get_all_args(): ---3-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"

日志一(POST请求，ngx.var.request_length=950, 大约delay了16s)
2016/05/13 14:35:47 [info] 51103#0: *155853488 [lua] gateway.lua:99: get_all_args(): ---1-----, client: 113.132.118.196, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "api.ffan.com"
2016/05/13 14:36:03 [info] 51103#0: *155853488 [lua] gateway.lua:103: get_all_args(): ---2-----, client: 113.132.118.196, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "api.ffan.com"

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

服务器配置：
32核cpu 128G内存 2个万兆网卡
nginx信息：
--prefix=/var/wd/gateway/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../echo-nginx-module-0.51 --add-module=../xss-nginx-module-0.04 --add-module=../ngx_coolkit-0.2rc1 --add-module=../set-misc-nginx-module-0.24 --add-module=../form-input-nginx-module-0.07 --add-module=../encrypted-session-nginx-module-0.03 --add-module=../srcache-nginx-module-0.25 --add-module=../ngx_lua-0.9.4 --add-module=../headers-more-nginx-module-0.25 --add-module=../array-var-nginx-module-0.03rc1 --add-module=../memc-nginx-module-0.14 --add-module=../redis2-nginx-module-0.10 --add-module=../redis-nginx-module-0.3.7 --add-module=../murmurhash-nginx-upstream-module-0.01 --add-module=../session-sticky-tengine-module-1.5.1 --add-module=../upstream-check-tengine-module-1.5.1 --add-module=../user_agent-tengine-module-1.5.1 --add-module=../nginx-delay-module-0.0.1 --add-module=../auth-request-nginx-module-0.2 --add-module=../rds-json-nginx-module-0.13 --add-module=../rds-csv-nginx-module-0.05 --with-ld-opt=-Wl,-rpath,/var/wd/gateway/luajit/lib --with-http_realip_module --with-http_stub_status_module --with-pcre=/root/gateway_ng/pcre-8.36 --with-http_spdy_module --with-http_addition_module --with-http_ssl_module

压力很低，大约 100tps
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

分析步骤
1.测试环境采用春哥开源的stap++中lj-lua-bt生成火焰图（附件 tmp.svg），个人能力不够，看不出问题.
2.生产环境关键点增加日志，最后确定产生delay的区域，如上面日志。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

问题：
1.什么因素会引起ngx.req.read_body()出现delay的情况
2.一般怎么根据火焰图分析问题

谢谢

doujiang24

Hello

你理解的对

read_body 是需要把 body 读完才算完成，而在此之前可能 body 还没有到达

在 2016年5月13日下午4:47，徐涛 <js...@163.com>写道：

我的理解是这样的。
ngx.req.read_body() 执行的时候，http请求的body数据没有全部到达，数据全部到达后，lua代码才继续执行

在 2016-05-13 15:46:28，"徐涛" <js...@163.com> 写道：

Hi：
生产环境中，最近发现lua代码偶尔出现delay的情况。出现频率大约万分之一,有的时候会delay超过几十秒。
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
通过增加打印日志，最后定位到引起delay的相关语句
ngx.log(ngx.INFO, "---1-----")
ngx.req.read_body()
ngx.log(ngx.INFO, "---2-----")
local post_args, err = ngx.req.get_post_args()
ngx.log(ngx.INFO, "---3-----")

相关日志
日志一(POST请求，ngx.var.request_length=998, 大约delay了40s)
2016/05/13 14:42:17 [info] 52172#0: *155912094 [lua] gateway.lua:98: get_all_args(): ---1-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"
2016/05/13 14:42:57 [info] 52172#0: *155912094 [lua] gateway.lua:101: get_all_args(): ---2-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"
2016/05/13 14:42:57 [info] 52172#0: *155912094 [lua] gateway.lua:103: get_all_args(): ---3-----, client: 218.10.137.226, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "m.test.com"

日志一(POST请求，ngx.var.request_length=950, 大约delay了16s)
2016/05/13 14:35:47 [info] 51103#0: *155853488 [lua] gateway.lua:99: get_all_args(): ---1-----, client: 113.132.118.196, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "api.ffan.com"
2016/05/13 14:36:03 [info] 51103#0: *155853488 [lua] gateway.lua:103: get_all_args(): ---2-----, client: 113.132.118.196, server: localhost, request: "POST /ffan/v1/mxlog HTTP/1.1", host: "api.ffan.com"

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

服务器配置：
32核cpu 128G内存 2个万兆网卡
nginx信息：
--prefix=/var/wd/gateway/nginx --add-module=../ngx_devel_kit-0.2.19 --add-module=../echo-nginx-module-0.51 --add-module=../xss-nginx-module-0.04 --add-module=../ngx_coolkit-0.2rc1 --add-module=../set-misc-nginx-module-0.24 --add-module=../form-input-nginx-module-0.07 --add-module=../encrypted-session-nginx-module-0.03 --add-module=../srcache-nginx-module-0.25 --add-module=../ngx_lua-0.9.4 --add-module=../headers-more-nginx-module-0.25 --add-module=../array-var-nginx-module-0.03rc1 --add-module=../memc-nginx-module-0.14 --add-module=../redis2-nginx-module-0.10 --add-module=../redis-nginx-module-0.3.7 --add-module=../murmurhash-nginx-upstream-module-0.01 --add-module=../session-sticky-tengine-module-1.5.1 --add-module=../upstream-check-tengine-module-1.5.1 --add-module=../user_agent-tengine-module-1.5.1 --add-module=../nginx-delay-module-0.0.1 --add-module=../auth-request-nginx-module-0.2 --add-module=../rds-json-nginx-module-0.13 --add-module=../rds-csv-nginx-module-0.05 --with-ld-opt=-Wl,-rpath,/var/wd/gateway/luajit/lib --with-http_realip_module --with-http_stub_status_module --with-pcre=/root/gateway_ng/pcre-8.36 --with-http_spdy_module --with-http_addition_module --with-http_ssl_module

压力很低，大约 100tps
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

分析步骤
1.测试环境采用春哥开源的stap++中lj-lua-bt生成火焰图（附件 tmp.svg），个人能力不够，看不出问题.
2.生产环境关键点增加日志，最后确定产生delay的区域，如上面日志。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

问题：
1.什么因素会引起ngx.req.read_body()出现delay的情况
2.一般怎么根据火焰图分析问题

谢谢

--

--