问题
参数校验问题
见到有人讨论java里的异常性能是好是坏,在业务代码里要不要用异常处理.
例如一些请求参数,到底是应该人工用if/else判断,还是通过异常统一处理,还是通过注解校验,抑或是其他方式呢?
这些方式对系统的性能会有什么实际影响呢?
日志运行信息问题
一般认为,java异常之所以慢,是因为需要获取当前的运行栈信息,而异常机制本身是常规性能消耗.
进而想到,一些通用的日志框架,比如log4j,logback,都是通过运行栈获取抛出异常的代码方法和运行行数的,官方文档也标注此类信息的打印会有较大的性能消耗.
而且我们也是通过类似的方式对jws的日志进行了增强.
那么性能到底会有有多差?
测试场景
运行环境
- jdk8 + idea 2016
- mac mini 2014 中配(硬盘非常慢,如有其它运行结果请联系)
- 非空机运行,所以结果不是非常准确
-
jvm配置
-client -Xcomp -Xmx1024m -Xms1024m,每次调用完后主动通知gc一次- 编译模式跟解析模式的结果相差非常大
异常创建
一般都说,使用异常之所以慢,是因为获取运行栈慢,那到底有多慢,慢在哪里,如果不获取异常栈的话速度又如何?
通过Throwable的源码可以得知,大部分的够着函数里都会调用java.lang.Throwable#fillInStackTrace()方法设置当前运行的异常栈,而这个方法慢的原因有:
- 方法本身是
synchronized,也就是对象级的同步 - 这个方法需要有一个native调用
- 需要获取当前运行栈的所有信息
另外,Throwable的很多方法也是synchronized的.
(不过线程栈信息本身有缓存,理论上第二次调用会快一些,而且异常一般不会在多个线程中处理)
所以理论上来说,只要把异常栈填充这一步去掉,异常对象应该是跟普通对象是差不多的.
刚好Throwalbe及各种Exception都有一个特殊的构造函数,可以跳过异常栈的获取.
protected Throwable(String message, Throwable cause,
boolean enableSuppression,
boolean writableStackTrace) {
...
}串行创建
| 普通对象 | HashMap | 省略异常栈 | 普通异常 | |
|---|---|---|---|---|
| 1000000个对象 | 35 | 38 | 48 | 1444 |
| 10000000个对象 | 30 | 62 | 99 | 10525 |
| 100000000个对象 | 269 | 593 | 936 | 112262 |
可以看到,关闭异常栈获取后,异常对象的创建跟普通对象基本一致,而获取异常栈则多了不止一个数量级的耗时.
并行创建
| 普通对象 | HashMap | 省略异常栈 | 普通异常 | |
|---|---|---|---|---|
| 10个线程,每个线程10000000个对象 | 223 | 728 | 534 | 73946 |
| 100个线程,每个线程1000000个对象 | 251 | 605 | 533 | 85106 |
| 500个线程,每个线程200000个对象 | 264 | 780 | 793 | 68589 |
在并行模式下的结果跟串行模式几乎一致.
异常处理
如果异常对象的创建的性能没有问题,那么try/catch块呢?
循环内外catch性能对比
根据java的try/catch运行原理,理论上来说,在不抛出异常的情况下,try/catch没有性能的消耗
| 没有try/catch | 循环外try/catch | 循环内try/catch | 循环内3次try/catch | |
|---|---|---|---|---|
| 运行10000000次 | 10 | 12 | 9 | 13 |
| 运行100000000次 | 43 | 49 | 53 | 45 |
| 运行500000000次 | 221 | 223 | 222 | 229 |
可以看到,当没有发生异常时,try/catch并不消耗性能.
throw/catch处理耗时
那么,对异常的throw/catch需要消耗多少性能呢?
| 没有throw/catch | throw/catch | |
|---|---|---|
| 运行10000000次 | 11 | 36 |
| 运行100000000次 | 51 | 113 |
| 运行500000000次 | 252 | 519 |
而当抛出异常时,try/catch本身的性能消耗也只是普通的代码性能消耗.
运行栈获取
通过运行栈获取当前执行的方法名和行数
通用的日志框架里都是通过运行栈去获取日志调用代码的方法名/行数等信息的,而且通过上述测试可以知道,这种方式会对性能代码比较大的影响.
通过往某个文件打印日志对运行信息获取的性能做测试.(使用非缓存式打印,一般日志框架默认都没有使用缓存打印)
串行
| 普通日志打印 | 运行信息日志打印 | |
|---|---|---|
| 打印10000行 | 297 | 533 |
| 打印100000行 | 535 | 2132 |
| 打印500000行 | 2576 | 8598 |
在串行模式下,通过运行栈获取调用信息确实会比普通的日志打印耗时多,可是可能因为磁盘io关系,性能差异没有异常对象与普通对象的差异大.
并行
| 普通日志打印 | 运行信息日志打印 | |
|---|---|---|
| 10个线程,每个线程打印100000行 | 7199 | 19511 |
| 20个线程,每个线程打印50000行 | 7600 | 20053 |
| 50个线程,每个线程打印20000行 | 7832 | 19031 |
在并发环境下,由于性能进一步被文件io限制,性能差异进一步缩小.
对系统QPS的影响
以上所有的测试都只是验证在一个非常纯粹的环境下的性能表现,其中甚至会有jvm的一些优化措施.
而实际业务处理中,会有框架,网络,业务处理等多种因素会影响系统的性能.
所以通过在本机搭建的一个基于jws的web工程来模拟实际的业务服务,通过ab测试相关的场景性能.
请求参数校验测试
建立一个有3个参数的请求,通过ab工具测试if/else和try/catch两种参数校验方式对性能的影响.
(数据单位:qps)
| if/else参数校验 | try/catch优化异常参数校验 | try/catch普通异常参数校验 | |
|---|---|---|---|
| 串行,5000请求 | 166.140 | 163.773 | 164.636 |
| 10并发,5000请求 | 206.59 | 206.22 | 203.06 |
| 50并发,5000请求 | 205.74 | 205.64 | 202.80 |
请求日志打印测试
根据统计平台,生产环境80%请求的耗时基本都在10ms附近,测试用例通过sleep的方式模拟每次请求有10ms的业务处理.
(考虑到机器问题,在本机器上10ms的业务处理应该算是一个很小的值了)
(数据单位:qps)
| 每次请求打印10行日志 | 每次请求打印20行日志 | 每次请求打印50行日志 | ||
|---|---|---|---|---|
| 串行,5000请求 | 普通日志 | 56.67 | 54.85 | 49.76 |
| 运行上线文日志 | 51.39 | 47.44 | 37.10 | |
| 10并发,5000请求 | 普通日志 | 59.54 | 57.27 | 52.78 |
| 运行上线文日志 | 55.81 | 48.96 | 38.57 |
结论
- 虽然即使经过优化后的异常性能也有一定的消耗,可是在异常校验这种场景下,一来因为发生频率小,二来因为执行次数少(一个请求只会出现一次try/catch),对业务请求的性能几乎没有影响.
- 而通过运行栈实现的日志增强,因为日志打印本身的高频率,所以对业务系统性能有一定的影响.
测试代码
异常测试用例
public class ExceptionCreate {
private static final String MSG = "test";
public static void run() throws Throwable {
serial(1000000);
serial(10000000);
serial(100000000);
parallel(10000000, 10);
parallel(5000000, 20);
parallel(2000000, 50);
}
private static void serial(int count) throws Throwable {
Util.print("---------- 串行创建[%s]个%s对象 ----------", count, "普通");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < count; i++) {
obj = new Util.NormalObject(MSG);
}
Util.print(obj);
});
Util.print("---------- 串行创建[%s]个%s对象 ----------", count, "HashMap");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < count; i++) {
obj = new HashMap<String, String>();
}
Util.print(obj);
});
Util.print("---------- 串行创建[%s]个%s对象 ----------", count, "省略异常栈Throwable");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < count; i++) {
obj = new Util.WithoutStackThrowalbe(MSG);
}
Util.print(obj);
});
Util.print("---------- 串行创建[%s]个%s对象 ----------", count, "省略异常栈异常");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < count; i++) {
obj = new Util.WithoutStackException(MSG);
}
Util.print(obj);
});
Util.print("---------- 串行创建[%s]个%s对象 ----------", count, "普通异常");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < count; i++) {
obj = new RuntimeException(MSG);
}
Util.print(obj);
});
}
private static void parallel(int countEachThread, int concurrentLevel) throws Throwable {
Util.print("---------- [%s]并行创建[%s]个%s对象 ----------", concurrentLevel, countEachThread, "普通");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < countEachThread; i++) {
obj = new Util.NormalObject(MSG);
}
Util.print(obj);
}, concurrentLevel);
Util.print("---------- [%s]并行创建[%s]个%s对象 ----------", concurrentLevel, countEachThread, "HashMap");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < countEachThread; i++) {
obj = new HashMap<String, String>();
}
Util.print(obj);
}, concurrentLevel);
Util.print("---------- [%s]并行创建[%s]个%s对象 ----------", concurrentLevel, countEachThread, "省略异常栈Throwable");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < countEachThread; i++) {
obj = new Util.WithoutStackThrowalbe(MSG);
}
Util.print(obj);
}, concurrentLevel);
Util.print("---------- [%s]并行创建[%s]个%s对象 ----------", concurrentLevel, countEachThread, "省略异常栈异常");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < countEachThread; i++) {
obj = new Util.WithoutStackException(MSG);
}
Util.print(obj);
}, concurrentLevel);
Util.print("---------- [%s]并行创建[%s]个%s对象 ----------", concurrentLevel, countEachThread, "普通异常");
Util.useTime(() -> {
Object obj = null;
for (int i = 0; i < countEachThread; i++) {
obj = new RuntimeException(MSG);
}
Util.print(obj);
}, concurrentLevel);
}
}try/catch测试用例
public class TryCatch {
public static void run() throws Throwable {
tryCatchPlace(10000000);
tryCatchPlace(100000000);
tryCatchPlace(500000000);
throwCatch(10000000);
throwCatch(100000000);
throwCatch(500000000);
}
public static void tryCatchPlace(int runCount) throws Throwable {
Util.print("---------- 没有try/catch运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
long total = 0;
for (int i = 0; i < runCount; i++) {
total = total + i;
}
Util.print(total);
});
Util.print("---------- 循环外try/catch运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
long total = 0;
try {
for (int i = 0; i < runCount; i++) {
total = total + i;
}
} catch (Exception e) {
e.printStackTrace();
}
Util.print(total);
});
Util.print("---------- 循环内1次try/catch运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
long total = 0;
for (int i = 0; i < runCount; i++) {
try {
total = total + i;
} catch (RuntimeException e) {
e.printStackTrace();
}
}
Util.print(total);
});
Util.print("---------- 循环内3次try/catch运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
long total = 0;
for (int i = 0; i < runCount; i++) {
try {
try {
try {
total = total + i;
} catch (Exception e) {
e.printStackTrace();
}
} catch (Exception e) {
e.printStackTrace();
}
} catch (RuntimeException e) {
e.printStackTrace();
}
}
Util.print(total);
});
}
private static void throwCatch(int runCount) throws Throwable {
RuntimeException existException = new RuntimeException("test");
Util.print("---------- 没有发生throw/catch运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
long total = 0;
for (int i = 0; i < runCount; i++) {
try {
if (i > -1) {
total = total + i;
} else {
throw existException;
}
} catch (RuntimeException ignore) {
total = total + i;
}
}
Util.print(total);
});
Util.print("---------- throw/catch运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
long total = 0;
for (int i = 0; i < runCount; i++) {
try {
if (i < -1) {
total = total + i;
} else {
throw existException;
}
} catch (RuntimeException ignore) {
total = total + i;
}
}
Util.print(total);
});
}
}日志测试用例
public class Log {
public static void run() throws Throwable {
util.Logger.redirectSystemOut(Logger.PRINT_FILE_PATH, () -> {
serial(10000);
serial(100000);
serial(500000);
parallel(100000, 10);
parallel(50000, 20);
parallel(20000, 50);
});
}
private static void serial(int runCount) throws Throwable {
Util.print("---------- 普通日志串行打印运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
for (int i = 0; i < runCount; i++) {
util.Logger.print("test");
}
});
Util.print("---------- 调用栈日志串行打印运行[%s]次耗时 ----------", runCount);
Util.useTime(() -> {
for (int i = 0; i < runCount; i++) {
util.Logger.printWithCaller("test");
}
});
}
public static void parallel(int runCountEachThread, int concurrentLevel) throws Throwable {
Util.print("---------- 普通日志[%s]并行打印运行[%s]次耗时 ----------", concurrentLevel, runCountEachThread);
Util.useTime(() -> {
for (int i = 0; i < runCountEachThread; i++) {
util.Logger.print("test");
}
}, concurrentLevel);
Util.print("---------- 调用栈日志[%s]并行打印运行[%s]次耗时 ----------", concurrentLevel, runCountEachThread);
Util.useTime(() -> {
for (int i = 0; i < runCountEachThread; i++) {
util.Logger.printWithCaller("test");
}
}, concurrentLevel);
}
}参数校验服务测试用例
(此用例基于jws,非jws环境无法运行)
public class ExceptionController extends Controller {
public static void noException(String a, Integer b, Boolean c, Long serviceTime) throws Exception {
if (StringUtils.isEmpty(a)) {
Util.render(ImmutableMap.of("code", 500, "msg", "a不能为空"));
}
if (b == null || b < 1) {
Util.render(ImmutableMap.of("code", 500, "msg", "b不能为空且要大于0"));
}
if (c == null || Boolean.FALSE.equals(c)) {
Util.render(ImmutableMap.of("code", 500, "msg", "c不能为空且必须为true"));
}
if (serviceTime != null && serviceTime > 0) {
Thread.sleep(serviceTime);
}
Util.render(ImmutableMap.of("a", a, "b", b, "c", c));
}
public static void fastException(String a, Integer b, Boolean c, Long serviceTime) throws Exception {
try {
if (StringUtils.isEmpty(a)) {
throw new FastException(500, "a不能为空");
}
if (b == null || b < 1) {
throw new FastException(500, "b不能为空且要大于0");
}
if (c == null || Boolean.FALSE.equals(c)) {
throw new FastException(500, "c不能为空且必须为true");
}
if (serviceTime != null && serviceTime > 0) {
Thread.sleep(serviceTime);
}
Util.render(ImmutableMap.of("a", a, "b", b, "c", c));
} catch (FastException e) {
Util.render(ImmutableMap.of("code", e.code, "msg", e.getMessage()));
}
}
public static void normalException(String a, Integer b, Boolean c, Long serviceTime) throws Exception {
try {
if (StringUtils.isEmpty(a)) {
throw new NormalException(500, "a不能为空");
}
if (b == null || b < 1) {
throw new NormalException(500, "b不能为空且要大于0");
}
if (c == null || Boolean.FALSE.equals(c)) {
throw new NormalException(500, "c不能为空且必须为true");
}
if (serviceTime != null && serviceTime > 0) {
Thread.sleep(serviceTime);
}
Util.render(ImmutableMap.of("a", a, "b", b, "c", c));
} catch (NormalException e) {
Util.render(ImmutableMap.of("code", e.code, "msg", e.getMessage()));
}
}
private static class FastException extends RuntimeException{
public final int code;
public FastException(int code, String msg) {
super(msg, null, false, false);
this.code = code;
}
}
private static class NormalException extends RuntimeException{
public final int code;
public NormalException(int code, String msg) {
super(msg);
this.code = code;
}
}
}日志服务测试用例
(此用例基于jws,非jws环境无法运行)
public class LogController extends Controller {
static {
try {
Logger.redirectSystemOut(Logger.PRINT_FILE_PATH);
} catch (Throwable throwable) {
throwable.printStackTrace();
}
}
public static void normalLog(int logCount) throws Throwable {
for (int i = 0; i < logCount; i++) {
Logger.print("test");
}
Thread.sleep(10);
Util.render("ok");
}
public static void enhanceLog(int logCount) throws Throwable {
for (int i = 0; i < logCount; i++) {
Logger.printWithCaller("test");
}
Thread.sleep(10);
Util.render("ok");
}
}其他代码
普通测试入口
public class TestPerformance {
public static void main(String args[]) throws Throwable {
ExceptionCreate.run();
TryCatch.run();
Log.run();
}
}日志组件
public class Logger {
public static final String PRINT_FILE_PATH = "/Users/jason/Downloads/print.txt";
private static volatile PrintStream usingOut = System.out;
public static void redirectSystemOut(String filePath, CheckedRunnable runnable) throws Throwable {
usingOut = new PrintStream(new FileOutputStream(filePath));
runnable.run();
usingOut.close();
usingOut = System.out;
}
public static void redirectSystemOut(String filePath) throws Throwable {
usingOut = new PrintStream(new FileOutputStream(filePath));
}
public static void print(String msg, Object... args) {
usingOut.println(String.format(msg, args));
}
public static void printWithCaller(String msg, Object... args) {
String[] infos = inferCallerInfos();
print("[%s.%s] %s", infos[0], infos[1], String.format(msg, args));
}
private static String[] inferCallerInfos() {
String[] infos = null;
try {
StackTraceElement stack[] = (new Throwable()).getStackTrace();
if (null != stack && stack.length >= 4) {
infos = new String[3];
StackTraceElement traceElement = stack[2];
//取具体类名
String classNames[] = traceElement.getClassName().split("\\.");
String className = classNames[classNames.length - 1];
String methodName = traceElement.getMethodName();
int lineNumber = traceElement.getLineNumber();
infos[0] = className;
infos[1] = methodName;
infos[2] = String.valueOf(lineNumber);
}
} catch (Exception e) {
jws.Logger.error(e, "[LoggerUtil.inferCallerInfos] happen error");
infos = null;
}
return infos;
}
}工具类
public class Util {
public static final Result EMPTY_RESULT = new Result() {
@Override
public void apply(Http.Request request, Http.Response response) {
}
};
public static void useTime(CheckedRunnable runnable) throws Throwable {
long beginTime = System.nanoTime();
runnable.run();
System.out.println(String.format("use time:[%s]", TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - beginTime)));
System.gc();
}
public static void useTime(CheckedRunnable task, int concurrentLevel) throws Throwable {
CountDownLatch begin = new CountDownLatch(1);
CountDownLatch finish = new CountDownLatch(concurrentLevel);
ExecutorService executor = Executors.newFixedThreadPool(concurrentLevel);
Stream.generate(() -> 1).limit(concurrentLevel).forEach(integer -> {
executor.submit(Unchecked.runnable(() -> {
begin.await();
task.run();
finish.countDown();
}));
});
useTime(() -> {
begin.countDown();
finish.await();
});
executor.shutdown();
}
public static void print(Object msg, Object... params) {
if (msg instanceof String) {
System.out.println(String.format((String) msg, params));
}
}
public static void render(Map<String, Object> params) throws IOException {
render(JSON.toJSONString(params));
}
public static void render(String result) throws IOException {
Http.Response response = Http.Response.current();
response.setContentTypeIfNotSet("application/json; charset=utf-8");
response.out.write(result.getBytes());
response.out.close();
throw EMPTY_RESULT;
}
public static class NormalObject {
private String msg;
public NormalObject(String msg) {
this.msg = msg;
}
}
public static class WithoutStackThrowalbe extends Throwable {
public WithoutStackThrowalbe(String message) {
super(message, null, false, false);
}
}
public static class WithoutStackException extends Throwable {
public WithoutStackException(String message) {
super(message, null, false, false);
}
}
}