agentzh

Hello!

2016-01-05 18:40 GMT-08:00 wonderbeyond:
> 我也刚注意到 `C1000(with accept_mutex on)` 的那个ab报告都是失败的，而且我又在同样条件下重复测试了多次还是全部报告失败。
> 测试的过程中，access.log全部是200输出，error.log没有任何错误输出，这是什么什么情况？我搞不懂了，好奇怪。我应该如何排查？
>
> 备注：同样情况，把C调到100，报告里面就不会有Failed requests了。

你的 worker_connections 配置太低了。开启 accept_mutex 时容易导致请求在各个 worker
之间分布不均匀。另外，请检查你的 error_log 配置指令是否配置了过高的过滤级别（比如 crit
之类），过高的话，你什么错误都不会看到的。worker_rlimit_nofile 指令在并发很高时可能也需要调整。

Regards,
-agentzh

wonderbeyond

> 你的 worker_connections 配置太低了。开启 accept_mutex 时容易导致请求在各个 worker
之间分布不均匀。

`C1000+accept_mutex on`那个测试，其它条件不变，我把worker_connections设置成10000，ab报告里面就没有失败的请求了。多谢！ （这是我的本地环境，配置比较干净，我们生产环境的worker_connections=65535）

> 另外，请检查你的 error_log 配置指令是否配置了过高的过滤级别（比如 crit
之类），过高的话，你什么错误都不会看到的。

多谢！被你说对了！我的error_log还是默认的配置，我把过滤级别设置成debug后，再重现有问题的那个`C1000+accept_mutex on`场景，发现错误日志大量输出如下：
2016/01/06 13:13:41 [info] 20716#0: *5052575 client closed connection while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
2016/01/06 13:13:41 [info] 20716#0: *5052642 client closed connection while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
ab的报告是全部失败，但其实这个时候你去看access.log，还是会有大量200输出的，我不解，难道是nginx在处理请求的时候和ab丢了连接？烦请春哥解释。

> worker_rlimit_nofile 指令在并发很高时可能也需要调整。
多谢指教，先记下这个指令，暂时没空测试了。
我平时对nginx的研究比较现实一点，主要面向业务需要。
随着对nginx的基本配置慢慢熟练起来（特别是概念），精力也得到了解放，现在也能尝试高级玩法了，以后不断跟你们飞！

--
work wonders together!

agentzh

Hello!

2016-01-05 21:26 GMT-08:00 wonderbeyond:
>> 2016/01/06 13:13:41 [info] 20716#0: *5052575 client closed connection
>> while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
>> 2016/01/06 13:13:41 [info] 20716#0: *5052642 client closed connection
>> while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
>
> ab的报告是全部失败，但其实这个时候你去看access.log，还是会有大量200输出的，我不解，难道是nginx在处理请求的时候和ab丢了连接？烦请春哥解释。
>

你贴的这些是 info 级别的，连警告（warn）都不是，更谈不上错误。

ab 报告的 Failed requests 也未必真的是失败，因为如果你的响应长度会发生变化，则 ab 也会认为是 Failed，并记录在
Length 那一子项里面。具体问题得具体分析。

在做性能测试和上生产时，用 debug 日志级别有些过了，毕竟刷错误日志也是高代价操作，很容易成为性能瓶颈。一般用 warn 就很够了。

Regards,
-agentzh

wonderbeyond

响应长度是不会变的，如果长度变化导致了ab报失败，那相同条件的c100测试一样会全报错。

从nginx日志看，ab的失败确实不是真失败，毕竟nginx的访问日志都是200。这说明哪里不靠谱，要么是ab，要么是nginx，导致我的测试不可信。

我等下继续用我的开发机看下，现在在上班路上。

2016年1月7日 06:56，"Yichun Zhang (agentzh)" <age...@gmail.com>写道：
Hello!

2016-01-05 21:26 GMT-08:00 wonderbeyond:
>> 2016/01/06 13:13:41 [info] 20716#0: *5052575 client closed connection
>> while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
>> 2016/01/06 13:13:41 [info] 20716#0: *5052642 client closed connection
>> while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
>
> ab的报告是全部失败，但其实这个时候你去看access.log，还是会有大量200输出的，我不解，难道是nginx在处理请求的时候和ab丢了连接？烦请春哥解释。
>

你贴的这些是 info 级别的，连警告（warn）都不是，更谈不上错误。

ab 报告的 Failed requests 也未必真的是失败，因为如果你的响应长度会发生变化，则 ab 也会认为是 Failed，并记录在
Length 那一子项里面。具体问题得具体分析。

在做性能测试和上生产时，用 debug 日志级别有些过了，毕竟刷错误日志也是高代价操作，很容易成为性能瓶颈。一般用 warn 就很够了。

Regards,
-agentzh

--

wonderbeyond

我留意到ab报告里面有关于Length的错误99744个，我觉得这是不可能的，应该是其它方面的问题，导致报告失误。

Failed requests:        100000
   (Connect: 0, Receive: 0, Length: 99744, Exceptions: 256)

我还改造了下lua service，看看到底每次生成的内容是否一样，最后观察日志，排除几百个异常的情况，剩下的9万多个输出都是一样的。

lua_shared_dict cache 10m;

server {
    listen 8011;
    location /lua {
        default_type text/plain;
        content_by_lua_block {
            local cjson = require 'cjson'
            local cache = ngx.shared.cache
            local json_data = cjson.encode(ngx.req.get_headers())
            local key = ngx.var.arg_ver
            cached = cache:get(key)
            if cached then
                ngx.log(ngx.ERR, (cached == json_data and 'equal' or 'not equal') .. ' with cached')
                ngx.say(json_data)
            else
                cache:set(key, json_data)
                ngx.log(ngx.ERR, 'Saved ' .. key .. ' in cache')
                ngx.say(json_data)
            end
        }
    }
}

测试命令是 ab -c1000 -n100000 'http://localhost:8011/lua?ver=abtest4'，结果就不贴出来了，跟之前一样全部报失败（Connect: 0, Receive: 0, Length: 99744, Exceptions: 256）

然后统计nginx error.log：

$ grep 'equal with' /var/log/nginx/error.log | grep 'abtest4' | wc -l
99743

也就是说有99743次响应的内容都跟第一次缓存的内容是一模一样的。

暂时到这里，不深究了。

​

在 2016年1月7日 上午7:44，wonderbeyond <wonde...@gmail.com>写道：

响应长度是不会变的，如果长度变化导致了ab报失败，那相同条件的c100测试一样会全报错。

从nginx日志看，ab的失败确实不是真失败，毕竟nginx的访问日志都是200。这说明哪里不靠谱，要么是ab，要么是nginx，导致我的测试不可信。

我等下继续用我的开发机看下，现在在上班路上。

2016年1月7日 06:56，"Yichun Zhang (agentzh)" <age...@gmail.com>写道：
Hello!

2016-01-05 21:26 GMT-08:00 wonderbeyond:
>> 2016/01/06 13:13:41 [info] 20716#0: *5052575 client closed connection
>> while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
>> 2016/01/06 13:13:41 [info] 20716#0: *5052642 client closed connection
>> while waiting for request, client: 127.0.0.1, server: 0.0.0.0:8011
>
> ab的报告是全部失败，但其实这个时候你去看access.log，还是会有大量200输出的，我不解，难道是nginx在处理请求的时候和ab丢了连接？烦请春哥解释。
>

你贴的这些是 info 级别的，连警告（warn）都不是，更谈不上错误。

ab 报告的 Failed requests 也未必真的是失败，因为如果你的响应长度会发生变化，则 ab 也会认为是 Failed，并记录在
Length 那一子项里面。具体问题得具体分析。

在做性能测试和上生产时，用 debug 日志级别有些过了，毕竟刷错误日志也是高代价操作，很容易成为性能瓶颈。一般用 warn 就很够了。

Regards,
-agentzh

--



--
work wonders together!