nginx 写⽇志对响应速度的影响探究（二）

前言

问题的提出是为了精细化提高 nginx(marxxx) 的性能，遂分析写日志对于请求的影响，上一篇《nginx写日志对于响应速度的影响探究（一）》中其实提出了两个问题还有待研究：

• log buffer 分别为 4k、64k、128k 不同情况下，相较而言 log buffer 为 64k 时 nginx 性能表现更优，这里的表现指 cpu 压满情况下 qps 更高。so why ?
• request time 成周期性波动，周期为 60s，即大概每 60s request time 会出现一个突峰，如下图。so why ？
  

过程

这里的记录将会比较简陋，因为完成之后发现实在没什么更好的干货，不过可以学习下探究的过程方法。

问题一

log buffer 分别为 4k、64k、128k 不同情况下，相较而言 log buffer 为 64k 时 nginx 性能表现更优，这里的表现指 cpu 压满情况下 qps 更高。so why ?

猜想

发现这个问题后，有个直观的感觉就是 nginx 每次根据 log buffer 的大小 dump log，即每次写磁盘的大小分别为 4k、64k、128k，写磁盘的大小较小就会导致写的次数过多，写的大小过大就会导致每次耗时较多，在 dump log 的次数与 dump log 的大小之间需要做一个平衡，故相对来看 64k 时表现较优。

这里有点类似 iostat -x 命令看到的 avgrq-sz，表示设备读写块大小（扇区数）。

那么是不是这样呢？

简单探究

探究过程略，基本方法就是固定其他条件，改变某一个变量（log buffer 大小），然后分别测试 nginx 性能，收集数据，然后绘制曲线图，进行对比分析。

• log buffer = 4k
  

• log buffer = 32k
  

• log buffer = 64k/128k
  

简单对比了小米监控收集的曲线图，还是能看到 log buffer 从 4k 到 32k，再到 64k/128k ，qps是增加了的。只是在 64k/128k 的时候比较不是很明显。

初步结论

通过上述对比，确实发现 log buffer 调整对 nginx 性能有影响，大致为 log buffer 64k 时性能最优！

问题二

request time 成周期性波动，周期为 60s，即大概每 60s request time 会出现一个突峰，如下图。so why ？

猜想

一般周期性波动的可能考虑到周期性的一些命令，比如 crontab 的任务，故可能是由于这些定时脚本执行引发了系统的抖动。

简单探究

探究方法很简单，多次测试，对比。测试的时候也是固定其他条件不变，改变某一个变量进行研究。这里的变量可能需要考虑很多，比如最终这次研究考虑到的一些变量有：

• 定时脚本影响
• log on / log off 影响
• 压测客户端的请求稳定度
• nginx 一些配置参数，比如 keep_alive影响
• 不同机器的影响
• 压测客户端与 nginx 是否位于同一台机器的影响

可以看到上面考虑了很多，也是由于探究过程一步步深入，一步步考虑更多的。这里可以对每次探究的变量进行下解释：

定时脚本

关闭这台机器所有定时任务，对比之前的曲线图。

log on /log off

关闭日志与否也可能是导致 request time 周期性突峰的原因，故分别对两种情况进行对比压测。

压测客户端请求稳定度

压测客户端能不能以均匀的速率稳定发出请求也可能导致 request time 周期性波动，这里的压测客户端先后使用了 wrk 和 ab 进行压测。

nohup wrk -c 100 -t 8 -d20m http://127.0.0.1:8088 -s /disk/ssd1/ngx/benchngx_logof
f.lua > /dev/null & 2>&1

ab -n 5000000 -c 8 -v 3 -k http://127.0.0.1:8088/ |grep 'X-Time' |cut -d ' '
 -f 2,3,4 >> off8jv13.a

其中 wrk -s 参数后面的是 lua 脚本：

-- Copyright 2017 smaug

local write = io.write
local unique_id = tostring( {} ):sub(8)
filename = string.format("/disk/ssd1/ngx/donev2/off8j_%s.a",unique_id)
file = io.open(filename,"a")
io.output(file)


response = function(status, headers, body)
   rtime = headers["X-RTime"]
   ltime = headers["X-LTime"]
   io.write(string.format("[%s] %s\n",ltime ,rtime))
end

每次请求后会执行函数，获取 header 中的某些字段，目的是在关闭日志后收集request time，由于 response body 很小，body 发送时间几乎可以忽略。此处 nginx 配置如下：

server {
    listen 8088;

   location / {
        return 200 "hello world xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx";
        #proxy_pass http://127.0.0.1:8089;
       #access_log /disk/ssd1/jmh/access.log simple buffer=32k;
       access_log off;
       error_log  off;
       add_header  X-RTime $request_time;
       add_header  X-LTime $time_local;
       add_header  X-Time '[$time_local] $request_time';
}

最后过滤日志文件得到 request time，当然这是关闭日志的情况下，如果没有关闭日志，自然只需要分析 access.log 文件即可。

ab -v 参数可以获取 response header ，使用 linux 管道等命令收集 request time，也是在关闭日志的情况下。

keep_alive

改变这个参数的值，进行对比压测。

不同机器

request time 波动的情况是否只是出现在这一台机器还是其他机器也会出现，故需要对比其他机器，对其他机器进行压测对比。

压测客户端（wrk/ab）与 nginx 是否位于同一台机器

压测客户端也是需要需要大量 cpu 资源的，甚至 I/O 资源，如果与 nginx 两者位于同一台机器，是否也可能对 nginx 产生影响呢？故让压测客户端从另外一台机器发起请求，然后对比分析。

初步结论

很遗憾，经过上述的探究，没有得出很确切的结论，request time 波动情况一直存在，不过可以注意到的是对不同机器进行压测的时候，我选择了好几台机器，其中包括我自己本地的一台虚拟机，就没有出现 request time 波动的情况，初步可以怀疑是那批机器本身的一些问题，可能是内核方面的问题，因为那批机器内核是经过了裁剪的。但不能确定，依然是模凌两可的结论。

末了

探究过程是一个比较无聊的过程，改变某个变量，重复的进行研究，想起了高中做的一些化学实验，确实比较无趣。

但是很多问题不可能是暴露在表面的，而且埋的很深，甚至最后都没法找到确切的根源，这些就需要很细心的分析，考虑的也要很周全，要根据当前的情况考虑更多的可能性，要排除一切可能导致的原因。这种分析过程，这种全面考虑问题的能力能得到提高和锻炼！