题图:Photo by Snapwire from Pexels
wrk 是一个非常棒的 HTTP 压力测试工具,构建在 Redis、NGINX、Node.js 和 LuaJIT 这几个开源项目的基础之上,充分利用了他们在事件驱动、HTTP 解析、高性能和灵活性方面的优点,并且可以自己写 Lua 脚本来生成测试请求。
虽然 wrk 没有测试案例,并且作者大概一年现身一次来合并代码,但这些并不妨碍我们把 wrk 作为性能测试和 fuzz 测试的首选工具。如果你还在使用多线程的 ab,那么非常值得尝试下 wrk。
下面是 wrk 结果中的延时分布统计部分:
1Latency Distribution
2 50% 1.20ms
3 75% 595.78ms
4 90% 899.11ms
5 99% 1.00s
这个示例是指,50% 的请求在 1.2ms 内完成,90% 的请求在 899 ms 内完成,99% 的请求在 1s 内完成。
我们在使用 wrk 压力测试自己产品的时候,发现 wrk 统计的延时结果中,大部分请求都是几毫秒内完成,但有一小部分请求的延时会超过 100 毫秒。 对于用 OpenResty 构建的系统,出现这么大的延时是不太科学的事情。
虽然这个问题最终解决方法非常简单,但具体的分析和定位有些曲折,花了好几天的时间。最终的解决方法并不重要,过程和思考问题的方式才是值得关注的。
遇到延迟问题,我们的第一反应是代码或者系统某个地方有阻塞。 由于系统比较复杂,所以我们祭出了火焰图。
没有现成的 systemtap 脚本来分析这类问题,所以花了点时间写脚本。但调整了几次 systemtap 脚本,都没有捕获到明显的延时,这个和 wrk 的结果明显不符。我们猜测这个脚本可能不够完善,可能遗漏了某些函数没有 hook 住。但同时也对 wrk 的结果是否正确产生了怀疑。
我们调转方向,先来定位到底是 wrk 统计错了,还是确实是 server 的问题。我们在 wrk 所在的服务器上,把压测期间的包都 dump 出来,按照耗时进行排序,惊奇的发现结果和 wrk 的延时统计大相径庭,没有发现超过 100 毫秒的请求。重复了几次以上测试,结果都一致。
这下目标就很明确了,只要把 wrk 关于延迟统计的代码捋顺就可以了。最担心的就是 wrk 内部统计时候有 bug,这就不好修复了,毕竟是一个没有任何测试案例的项目。
我们仔细过了一遍 wrk 的统计逻辑,并在开始和结束的地方加了日志,发现关于延时的统计都是正确的,这也让我们松了一口气。但是在打印最终结果之前,有一段统计数据校正
的代码:
1if (complete / cfg.connections > 0) {
2 int64_t interval = runtime_us / (complete / cfg.connections);
3 stats_correct(statistics.latency, interval);
4}
按照这个 if 判断,只要有压测数据产生,就会进行校正。有兴趣的同学,可以去看看 stats_correct
函数的代码,只有 10 行,我看了几遍也没看懂。
再去查代码的提交记录,说不定有什么收获,但只有下面这一行,又没看懂:
1remove calibration & improve CO correction
吐槽下,如果提交记录稍微详细一点儿,不用缩写,或者加个代码注释,就能省不少事儿。
问题查到这里,已经可以证实不是产品的问题,而且解决方法已经有了,就是注释掉上面这段校正的代码。但 wrk 作者特意加上肯定是有原因的,不明白这个原因始终是个隐患。自然的,要开一个 issue 来请教下作者,一年现身一次的 wg 在 15 天后给了答复,原来上面 commit info 里面的缩写 CO
是指 Coordinated Omission
,并且给了一篇专门讲这个问题的文章,感兴趣的同学可以用这个关键字自行搜索。
简单的说,Coordinated Omission
是指在做压力测试的时候,只统计发送和收到回复之间的时间是不够的,这个是指服务时间
,会遗漏掉很多潜在的问题,还需要把测试请求的等待时间也计算在内,才算是用户关心的响应时间
。
提出 CO 这个问题的 Gil Tene,还对 wrk 做了修改,专门解决 CO 的问题: https://github.com/giltene/wrk2,在这个项目的 README 里面也有一些对此的解释,有兴趣的可以看看,这里就不多提及了。
对于我们自己的产品来说,代码中肯定不会有任何阻塞,在做压力测试的时候,是会把 CPU 跑满。即使出现阻塞,也是有火焰图来采样分析的。所以 wrk 这里针对 Coordinated Omission 做的简单粗暴的校正,反而会产生误导。