今天填一下之前的坑,前文性能测试误差对比研究(一)中,我对几种比较常见的性能测试误差来源,进行了对比测试。效果还是不错的,基本的结论都是非常清晰的。
今天我继续分享剩下几种性能测试误差来源对性能测试误差影响,以及定量测试其中的影响程度。
测试脚本
由于FunTester已经优化了性能测试框架软启动的问题,总体测试的时间会比较长,所以我这里简单实现了一个简化统计,在测试过程中表现还是很不错的。分享一下Groovy
脚本:
- 这个脚本会在后面测试中略微修改。
package com.funtester.groovy
import com.funtester.frame.SourceCode
import com.funtester.utils.Time
import java.util.concurrent.CountDownLatch
import java.util.concurrent.atomic.AtomicInteger
/**
* 结束控制
*/
class FunTester extends SourceCode {
static Vector<Long> costs = new Vector<>()
static CountDownLatch countDownLatch;
private static final int thread = 20//线程数
private static final int times = 50//单线程次数
private static final AtomicInteger excutetimes= new AtomicInteger()
static void main(String[] args) {
countDownLatch = new CountDownLatch(thread)
def s = Time.getTimeStamp()
thread.times {
new FunTest().start()
}
countDownLatch.await()
def e = Time.getTimeStamp()
def rts = []
costs.each {rts << it}
def rt = rts.sum() / rts.size()
double qps = thread * 1000.0 / rt
double qps2 = excutetimes.get() * 1000.0 / (e - s)
def deviation = com.funtester.frame.SourceCode.getPercent(Math.abs(qps - qps2) * 100 / Math.max(qps, qps2))
output("通过平均时间计算QPS:$qps")
output("通过总时间计算QPS:$qps2")
output("误差是:$deviation")
}
private static class FunTest extends Thread {
@Override
void run() {
times.times {
def start = Time.getTimeStamp()
sleep(0.1)
def end = Time.getTimeStamp()
excutetimes.getAndIncrement()
costs.add(end - start)
}
countDownLatch.countDown()
}
}
}
有些小伙伴表示Groovy
脚本比较晦涩难懂,下面是Java
版本:
package com.funtester.java;
import com.funtester.frame.SourceCode;
import com.funtester.utils.Time;
import java.util.ArrayList;
import java.util.List;
import java.util.Vector;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.atomic.AtomicInteger;
/**
* 结束控制
*/
public class FunTester extends SourceCode {
static Vector<Long> costs = new Vector<>();
static CountDownLatch countDownLatch;
private static final int thread = 20;//线程数
private static final int times = 50;//单线程次数
private static final AtomicInteger excutetimes = new AtomicInteger();
static void main(String[] args) throws InterruptedException {
countDownLatch = new CountDownLatch(thread);
long s = Time.getTimeStamp();
for (int i = 0; i < thread; i++) {
new FunTest().start();
}
countDownLatch.await();
long e = Time.getTimeStamp();
List rts = new ArrayList();
costs.forEach(f -> rts.add(f));
long count = rts.stream().count();
long rt = count / rts.size();
double qps = thread * 1000.0 / rt;
double qps2 = excutetimes.get() * 1000.0 / (e - s);
String deviation = getPercent(Math.abs(qps - qps2) * 100 / Math.max(qps, qps2));
output("通过平均时间计算QPS:" + qps);
output("通过总时间计算QPS:" + qps2);
output("误差是:" + deviation);
}
private static class FunTest extends Thread {
@Override
public void run() {
for (int i = 0; i < times; i++) {
long start = Time.getTimeStamp();
SourceCode.sleep(0.1);
long end = Time.getTimeStamp();
excutetimes.getAndIncrement();
costs.add(end - start);
}
countDownLatch.countDown();
}
}
}
首先跑一个 20 线程,50 次数的基准测试,结果如下:
INFO-> 当前用户:fv,工作目录:/Users/fv/Documents/workspace/funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 通过平均时间计算QPS:193.4142449591
INFO-> 通过总时间计算QPS:189.5375284306
INFO-> 误差是:2%
Process finished with exit code 0
异步结束
上面的例子是一个sleep
固定时间的,然后执行完所有的循环次数以后再通知结束,等所有线程执行结束之后再进行数据统计工作。
概率上讲所有的线程应该是会在某一个很短的时间间隔内结束执行,但是实际情况中大多都不是这个理想模型。很多因素,包括接口执行时间分布不均匀、各个线程执行任务并不一致、异常处理消等等原因会导致各个线程在结束时间点上差别比较大,导致误差偏大,当然在固定时间请求模式中不存在这个问题。
下面是我修改run()
方法内容。
@Override
void run() {
times.times {
def start = Time.getTimeStamp()
sleep(0.1 + getRandomDouble() / 3)
def end = Time.getTimeStamp()
excutetimes.getAndIncrement()
costs.add(end - start)
}
countDownLatch.countDown()
}
在 20 线程,50 次数的情况下测试数据如下:
INFO-> 当前用户:fv,工作目录:/Users/fv/Documents/workspace/funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 通过平均时间计算QPS:75.8204722857
INFO-> 通过总时间计算QPS:70.2641933671
INFO-> 误差是:7.33%
Process finished with exit code 0
明显误差开始增加了。下面测试增加线程到 40,测试结果如下:
INFO-> 当前用户:fv,工作目录:/Users/fv/Documents/workspace/funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 通过平均时间计算QPS:148.2708834906
INFO-> 通过总时间计算QPS:130.3101381287
INFO-> 误差是:12.11%
Process finished with exit code 0
误差持续增加,下面我保持 20 线程,增加次数到 100,结果如下:
INFO-> 当前用户:fv,工作目录:/Users/fv/Documents/workspace/funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 通过平均时间计算QPS:73.8407918687
INFO-> 通过总时间计算QPS:68.8373373718
INFO-> 误差是:6.78%
Process finished with exit code 0
误差反而降下来了,这也是符合概率学中,实验次数越多,实验结果越是趋近于理论值。
结论比较明显了,在随机不确定请求耗时的情况下,增加线程会增加误差,增加请求次数会降低误差。总体讲在多线程,低请求次数中,QPS 的误差还是比较大的,在性能测试中,应当增加请求次数来平衡这个误差。
下面我引入private static boolean KEY = false//控制线程结束
来控制所有的线程一起结束。
重写run()
方法如下:
@Override
for ( int i in 0..<times ) {
def start = Time.getTimeStamp()
sleep(0.1 + getRandomDouble() / 3)
def end = Time.getTimeStamp()
excutetimes.getAndIncrement()
costs.add(end - start)
if (KEY) break
}
KEY = true
countDownLatch.countDown()
这里Groovy
没有跳出循环的机制,所以只能换成for
循环形式了,这是我始料未及的,差点翻车了。
同样在 40 线程,50 次数的情况下,测试结果如下:
INFO-> 当前用户:fv,工作目录:/Users/fv/Documents/workspace/funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 通过平均时间计算QPS:149.5957705046
INFO-> 通过总时间计算QPS:145.44
INFO-> 误差是:2.78%
Process finished with exit code 0
可以看到,误差明显下降了不少,QPS 反而增加了一些,哈哈。这里不多讲了。
日志打印
下面分享一下性能测试中对日志记录对性能测试的影响,这里我用的log4j2
日志组件,没有使用异步日志打印,所以影响应该会相比异步打印稍大一些。
首先分享一个数据,在我使用自己封装的moco
服务的测试中,关闭日志情况下QPS
可以达到将近 3 万,在开启日志记录的情况下QPS
只能到 5 千。有兴趣的童鞋可以翻看以前的文章:
- 解决 moco 框架 API 在 post 请求 json 参数情况下 query 失效的问题
- 给 moco API 添加 limit 功能
- 给 moco API 添加 random 功能
- 解决 moco 框架 API 在 cycle 方法缺失的问题
- 五行代码构建静态博客
- moco API 模拟框架视频讲解(上)
- moco API 模拟框架视频讲解(中)
- moco API 模拟框架视频讲解(下)
- 如何 mock 固定 QPS 的接口
- mock 延迟响应的接口
- moco 固定 QPS 接口升级补偿机制
回到正题,我继续采用固定sleep
的模型进行测试,run
方法如下:
@Override
void run() {
times.times {
def start = Time.getTimeStamp()
sleep(0.1)
10.times {
logger.info(text)
}
def end = Time.getTimeStamp()
excutetimes.getAndIncrement()
costs.add(end - start)
}
countDownLatch.countDown()
}
添加属性private static Logger logger = LogManager.getLogger(FunTester.class);
和private static String text = getManyString("FunTester",100)
。
在 20 线程,50 次记录的模式下,测试结果如下:
INFO-> 通过平均时间计算QPS:186.3620268734
INFO-> 通过总时间计算QPS:182.5150574922
INFO-> 误差是:2.06%
误差虽然不大,但是对比基准测试的结果:
INFO-> 通过平均时间计算QPS:193.4142449591
INFO-> 通过总时间计算QPS:189.5375284306
INFO-> 误差是:2%
明显QPS
有了较大的影响,所以这个题目的研究内容并不仅仅是误差,还有对 QPS 的影响。下面增加线程到 40 线程,结果如下:
INFO-> 通过平均时间计算QPS:347.3654501639
INFO-> 通过总时间计算QPS:339.328130302
INFO-> 误差是:2.31%
对比基准测试的 40 线程测试结果:
INFO-> 通过平均时间计算QPS:384.8059375556
INFO-> 通过总时间计算QPS:380.8073115004
INFO-> 误差是:1.04%
此时QPS
下降尤为明显,已经达到 10% 以上了。下面继续增加循环次数到 100,看看结果如何:
INFO-> 通过平均时间计算QPS:364.3792003243
INFO-> 通过总时间计算QPS:352.8581510233
INFO-> 误差是:3.16%
对比基准测试结果:
INFO-> 当前用户:fv,工作目录:/Users/fv/Documents/workspace/funtester/,系统编码格式:UTF-8,系统Mac OS X版本:10.16
INFO-> 通过平均时间计算QPS:388.6098454304
INFO-> 通过总时间计算QPS:384.6893633391
INFO-> 误差是:1.01%
Process finished with exit code 0
QPS 有所升高,但是误差稍微有些增加。大致结论如下:少量(远未达到硬件 IO 瓶颈前)日志记录,在QPS
方面影响较大,甚至能达到10%
以上,随着线程增加,QPS
降低越来越大,随着请求次数增加,QPS
下降趋势减缓。在误差方面,增加日志记录,自然会导致QPS
误差变大。主要是因为打印日志消耗时间,算在总时间内和算在请求耗时的区别。案例中我是算在了请求时间内,所以算出来的误差很低,但是如果将日志打印计算在请求时间之外,误差将会很大。
所以在以后的性能测试过程中,尽量避免记录日志。