ngx.req.read_body() 花费 27~70 millisecs

[黄川]

各位大神，遇到一个棘手的问题，我发现我们的request latency比较高，用如下code profile之后发现ngx.req.read_body()会耗费27-70毫秒 (0.027-0.7s，好像要么0.03s左右要么0.065秒左右，没有中间的)，这一个函数占用了绝大部份的时间，不知道是否大家见过这个问题？是不是只能这么读request? 谢谢！

      location = /reqest {

            client_max_body_size 50k;

            client_body_buffer_size 50k;

            content_by_lua_block {

                start_time = ngx.now()

                log(WARN, "=====1:  ", ngx.now() - start_time)

                -- explicitly read the req body

                ngx.req.read_body()

                

                log(WARN, "=====2:  ", ngx.now() - start_time)

                local data = ngx.req.get_body_data()

                if not data then

                    ngx.status = 204

                    ngx.header.content_type = 'text/html'

                    ngx.say("")

                    return

                end

                log(WARN, "=====3:  ", ngx.now() - start_time)

2016/02/17 23:00:58 [warn] 30721#0: *327 [lua] content_by_lua(nginx.conf:196):24: =====1:  0, client: 192.48.237.171, server: localhost, request: "POST /ad_server_v2_bin HTTP/1.1", host: "mopub.frac

tionalmedia.com:443"

2016/02/17 23:00:58 [warn] 30721#0: *326 [lua] content_by_lua(nginx.conf:196):28: =====2:  0.067000150680542, client: 192.48.237.171, server: localhost, request: "POST /ad_server_v2_bin HTTP/1.1", h

ost: "mopub.fractionalmedia.com:443"

2016/02/17 23:00:58 [warn] 30721#0: *326 [lua] content_by_lua(nginx.conf:196):37: =====3:  0.067000150680542, client: 192.48.237.171, server: localhost, request: "POST /ad_server_v2_bin HTTP/1.1", h

ost: "mopub.fractionalmedia.com:443"

[黄川]

POST里面的数据就是简单的json

data={"app":{"bundle":"661041542","cat":["IAB1","IAB3","entertainment","productivity"],"id":"ba7c910fd50c44359a73ac3466e08c81","name":"vDL (Georg Young)","publisher":{"id":"ce5416f959f949c4bd2d748f2df511a2","name":"LAMETINA HOLDINGS LTD."},"storeurl":"https://itunes.apple.com/app/id661041542","ver":"1.7"},"at":2,"bcat":["IAB7-39","IAB9-9","IAB25","IAB26"],"device":{"carrier":"520-03","connectiontype":3,"devicetype":1,"dnt":0,"dpidmd5":"1fbf8cfc5c5f093c621659a6494b322b","dpidsha1":"bcf9b8da0dd2af7670ffeb442def46eed7a76638","ext":{"idfa":"5D801360-0E2F-472F-B8D2-8A098E51BA17"},"geo":{"city":"Bangkok","country":"THA","region":"40"},"ip":"49.230.57.7","js":1,"language":"th","make":"Apple","model":"iPhone 4S","os":"iOS","osv":"7.0.4","ua":"Mozilla/5.0 (iPhone; CPU iPhone OS 7_0_4 like Mac OS X) AppleWebKit/537.51.1 (KHTML, like Gecko) Mobile/11B554a"},"id":"1748b105-e8c5-4feb-bef5-348200ad02cc","imp":[{"banner":{"api":[3,5],"battr":[8,9,10,14,6],"btype":[4],"ext":{"nativebrowserclick":1},"h":50,"pos":1,"w":320},"bidfloor":0.080,"displaymanager":"mopub","displaymanagerver":"3.3.0","ext":{"secure":0},"id":"1","instl":0,"tagid":"de520c4ccb0f4f94af8dc22298dd03b4"}]}

[Yichun Zhang (agentzh)]

Hello!

2016-02-17 15:07 GMT-08:00 黄川:
> 各位大神，遇到一个棘手的问题，我发现我们的request latency比较高，用如下code
> profile之后发现ngx.req.read_body()会耗费27-70毫秒
> (0.027-0.7s，好像要么0.03s左右要么0.065秒左右，没有中间的)，这一个函数占用了绝大部份的时间，不知道是否大家见过这个问题？是不是只能这么读request?

ngx.req.read_body() 调用的是 nginx 核心中的请求体读取函数。nginx 核心就是这么读请求体的。

读取请求体会涉及客户端 I/O，所以客户端与你的服务器之间的网络延时会计算在内。

如果可以排除网络链路上的延时，则可以检查你的 nginx worker 进程的事件处理循环是否存在阻塞，无论是 off-CPU 的阻塞还是
on-CPU 的阻塞，使用下面的工具可以计量 nginx epoll 事件处理循环中的阻塞效应：

https://github.com/openresty/stapxx#epoll-loop-blocking-distr

如果确认存在较严重的阻塞，则可以使用火焰图工具分析原因（如果 CPU 占用接近 100%，则应使用 on-CPU
火焰图进行分析，相反，如果很低，则应使用 off-CPU 火焰国图分析，其他情况两者都应使用）：

https://openresty.org/#Profiling

一般都是低级的 Lua 编程错误或配置错误导致的阻塞。

Regards,
-agentzh

[黄川]

>> 读取请求体会涉及客户端 I/O，所以客户端与你的服务器之间的网络延时会计算在内。 

nginx为什么要同客户端交互取到body? 客户端post一个请求，nginx读取body需要再通过tcp啥的去客户端读？还是什么意思？

春哥你说的解释了我一些case。我现在测试的是twitter的ads服务，有意思的事情我们现有twitter production请求，read_body基本上没有延迟，但是我们想升级协议，twitter对我们进行认证时候这个延迟就出现呢

如果我用lua_need_request_body会不会有帮助？不过如果每个请求还要去客户端读body估计延迟就避免不了了。。

[黄川]

如果enable lua_need_request_body， 看上去要body缓存好了才会叫request handler。也看了下ngx_http_read_client_request_body，如何verify是read_body()是网络延迟？

[黄川]

找不到stap++为什么？google了下没找到原因。。

user@nhbid49:~/bidder/stapxx$ stap -V

Systemtap translator/driver (version 2.6/0.158, non-git sources)

Copyright (C) 2005-2014 Red Hat, Inc. and others

This is free software; see the source for copying conditions.

enabled features: TR1_UNORDERED_MAP NLS

user@nhbid49:~/bidder/stapxx$ ./samples/epoll-loop-blocking-distr.sxx -x 4552 --arg time=60

/usr/bin/env: stap++: No such file or directory

[Yichun Zhang (agentzh)]

Hello!

2016-02-17 17:03 GMT-08:00 黄川:
>>> 读取请求体会涉及客户端 I/O，所以客户端与你的服务器之间的网络延时会计算在内。
> nginx为什么要同客户端交互取到body?

貌似你的理解存在问题。这里不存在真正意义上的“交互”啊，只是 nginx 在接收请求体数据而已。

> 客户端post一个请求，nginx读取body需要再通过tcp啥的去客户端读？还是什么意思？

读取请求数据，无论是请求头还是请求体，自然都是从 TCP 连接上读取的。当请求头和请求体不能放进一个 packet 中时，自然会拆分为多个
packet 在线路上面传输，所以当你调用 ngx.req.read_body() 时，（一部分）请求体数据所在的 packet
可能还没有到达（即这个 packet 和请求头所在的 packet 没有同步到达）。这都是很正常的现象。

> 春哥你说的解释了我一些case。我现在测试的是twitter的ads服务，有意思的事情我们现有twitter
> production请求，read_body基本上没有延迟，但是我们想升级协议，twitter对我们进行认证时候这个延迟就出现呢

你可以在 TCP 层面上检查 packet 的拆分和到达情况。

> 如果我用lua_need_request_body会不会有帮助？不过如果每个请求还要去客户端读body估计延迟就避免不了了。。
>

lua_need_request_body 也是调用的 nginx 核心中的请求体读取函数，几乎所有 nginx 模块都是使用的此例程，包括
ngx_proxy, ngx_fastcgi, ngx_uwsgi 这些模块。并不会有任何区别啊。代码路径都是完全一样的。

> 找不到stap++为什么？google了下没找到原因。。

stap++ 是 stapxx 仓库里的命令。建议仔细阅读 stapxx 的 README 文档。

Regards,
-agentzh

[XI WANG]

stapxx目录export到path环境变量。

[黄川]

请问下下面错误是不是要装kernel debuginfo? 因为觉得ubuntu上有点麻烦，想确认下再弄。。

root@nhbid49:~/bidder/stapxx# ./samples/epoll-loop-blocking-distr.sxx -v -x 4552 --arg time=10

Pass 1: parsed user script and 106 library script(s) using 61904virt/30656res/2212shr/29244data kb, in 70usr/0sys/77real ms.

semantic error: while resolving probe point: identifier 'syscall' at <input>:8:7

        source: probe syscall.epoll_wait.return {

                      ^

semantic error: no match

semantic error: while resolving probe point: identifier 'syscall' at :14:7

        source: probe syscall.epoll_wait {

                      ^

semantic error: no match

Pass 2: analyzed script: 3 probe(s), 139 function(s), 3 embed(s), 2 global(s) using 63096virt/32828res/3112shr/30436data kb, in 100usr/260sys/354real ms.

Pass 2: analysis failed.  [man error::pass2]

[Yichun Zhang (agentzh)]

Hello!

2016-02-17 21:09 GMT-08:00 黄川:
> 请问下下面错误是不是要装kernel debuginfo? 因为觉得ubuntu上有点麻烦，想确认下再弄。。
>
> root@nhbid49:~/bidder/stapxx# ./samples/epoll-loop-blocking-distr.sxx -v -x
> 4552 --arg time=10
> Pass 1: parsed user script and 106 library script(s) using
> 61904virt/30656res/2212shr/29244data kb, in 70usr/0sys/77real ms.
> semantic error: while resolving probe point: identifier 'syscall' at
> <input>:8:7
> source: probe syscall.epoll_wait.return {
> ^

是的。需要 kernel-devel 包和 kernel-debuginfo 包（这是 redhat 家族发行版里的包名，不清楚
ubuntu 上面的具体包名）。

Regards,
-agentzh

[Zexuan Luo]

ubuntu上的安装方法可以参考下这份wiki https://wiki.ubuntu.com/Kernel/Systemtap

在 2016年2月18日星期四 UTC+8下午1:21:28，agentzh写道：

[黄川]

谢谢大家回答！

update: 我们的延迟主要是因为https，链接没有重用导致每次都handshake。

[Yichun Zhang (agentzh)]

Hello!

2016-02-20 14:32 GMT-08:00 黄川:
> update: 我们的延迟主要是因为https，链接没有重用导致每次都handshake。
>

哦……难怪。如果是下游连接，应启用 SSL session reuse 和 HTTP keepalive；如果是上游连接，应启用连接池。

Regards,
-agentzh