Java異常及相關呼叫效能測試
問題
引數校驗問題
見到有人討論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);
}
}
}
相關文章
- log列印及異常處理相關
- iOS 應用效能測試的相關方法、工具及技巧iOS
- Java自定義異常的建立及多層呼叫Java
- 【DG】搭建（二）及相關測試
- Java中測試異常的多種方式Java
- 集合差異比較演算法及效能測試演算法
- Oracle DB 壓力測試相關效能指標及達到指標的方法Oracle指標
- Java常見異常及解釋Java
- 異常-自定義異常的實現和測試
- 網路異常測試初探
- python自動化測試之異常及日誌Python
- Java Map遍歷方式方式及效能測試Java
- 效能測試——效能測試-常見效能指標-總體概況指標
- Java 常見異常及趣味解釋Java
- 學習 java 做自動化測試相關Java
- JNI/NDK開發指南(9)：JNI呼叫效能測試及優化優化
- 效能測試之常見效能指標指標
- 異常測試實踐與梳理
- (原)發動機油指標及相關測試指標
- 效能測試常見面試題面試題
- 測試 web程式，tomcat出現java.lang.OutOfMemoryError異常。WebTomcatJavaError
- JAVA 異常對於效能的影響Java
- 軟體效能測試常見指標。在哪裡測試測試？指標
- 【測試】Android Studio 相關下載及引數Android
- junit 使用JUnit測試預期異常
- 01_效能測試的關鍵效能指標及收集方式（windows）指標Windows
- 關於java中空指標異常的原因及解決方法Java指標
- 效能測試學習(1)-效能測試分類與常見術語
- 常見埠及安全測試
- 異常執行緒的相關複習（前）執行緒
- 技術乾貨：關於效能測試面試題及答案面試題
- Java 7：最新特性更新、程式碼示例及效能測試（轉）Java
- Java應用異常狀態監測Java
- 壓力測試相關指標指標
- oracle鎖級別相關測試Oracle
- 軟體效能測試常見指標指標
- 【Java初探01】——Java簡介及相關Java
- Java異常Java