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 进行压测。

1
2
3
4
5
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 脚本:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
-- 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 配置如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
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 波动的情况,初步可以怀疑是那批机器本身的一些问题,可能是内核方面的问题,因为那批机器内核是经过了裁剪的。但不能确定,依然是模凌两可的结论。

末了

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

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

Smaug wechat
扫一扫,手机访问本站
客官给点小费吧
分享到: