前段時間，公司里組織了一次代碼檢查，其中有一條檢查項讓我有些費解：

所有INFO和DEBUG級別的日志，必須加上isInfoEnabled和isDebugEnabled的判斷。

理由是大量的不輸出的日志對性能會有影響（日志中存在字符串拼接）。如果說只是DEBUG的加上，我也就認了，可是在系統中寫成INFO的日志如果不輸出，那還寫它干嘛，我就是想看到關鍵路徑的日志。而且在大多數日志上加上這么一個判斷真的很難看。。。

?

所謂上有政策，下有對策，于是有人開始寫一些包裝了判斷的輔助類，當中用這樣的代碼（截取）：

Java代碼??

public?class?LogUtil?{??

??

????public?static?void?info(Logger?logger,?String?message)?{??

????????if?(logger.isInfoEnabled())?{??

????????????logger.info(message);??

????????}??

????}??

??

????public?static?void?debug(Logger?logger,?String?message)?{??

????????if?(logger.isDebugEnabled())?{??

????????????logger.debug(message);??

????????}??

????}??

??

????public?static?void?debug(Logger?logger,?String?message,?Throwable?throwable)?{??

????????if?(logger.isDebugEnabled())?{??

????????????logger.debug(message,?throwable);??

????????}??

????}??

}??

但這樣的代碼真的就能解決問題了嗎？答案是“不能”！字符串拼接還存在。

?

那讓我們分兩個部分來看一下這個問題：

日志中的字符串拼接真的對性能影響很大嗎

加不加isInfoEnabled的性能差距究竟有多少

關于第一個問題，String的拼接是不修改原來的字符串的，而是創建一個新的String對象，道理上是這么說的，我們也該這么理解。但Java編譯器并不傻，實際情況是怎么樣的呢，它會做些優化。請看如下代碼：

Java代碼??

public?class?StringAddDemo?{??

????public?static?void?main(String[]?args)?{??

????????String?a?=?"abc";??

????????String?b?=?a?+?"def";??

????????System.out.println(b?+?"ghi");??

????}??

}??

在編譯后，通過javap -c StringAddDemo看看結果：

javap結果 Compiled from "StringAddDemo.java"
public class StringAddDemo extends java.lang.Object{
public StringAddDemo();
? Code:
?? 0:?? aload_0
?? 1:?? invokespecial?? #1; //Method java/lang/Object."<init>":()V
?? 4:?? return

public static void main(java.lang.String[]);
? Code:
?? 0:?? ldc???? #2; //String abc
?? 2:?? astore_1
?? 3:?? new???? #3; //class java/lang/StringBuilder
?? 6:?? dup
?? 7:?? invokespecial?? #4; //Method java/lang/StringBuilder."<init>":()V
?? 10:? aload_1
?? 11:? invokevirtual?? #5; //Method java/lang/StringBuilder.append:(Ljava/lang/
String;)Ljava/lang/StringBuilder;
?? 14:? ldc???? #6; //String def
?? 16:? invokevirtual?? #5; //Method java/lang/StringBuilder.append:(Ljava/lang/
String;)Ljava/lang/StringBuilder;
?? 19:? invokevirtual?? #7; //Method java/lang/StringBuilder.toString:()Ljava/la
ng/String;
?? 22:? astore_2
?? 23:? getstatic?????? #8; //Field java/lang/System.out:Ljava/io/PrintStream;
?? 26:? new???? #3; //class java/lang/StringBuilder
?? 29:? dup
?? 30:? invokespecial?? #4; //Method java/lang/StringBuilder."<init>":()V
?? 33:? aload_2
?? 34:? invokevirtual?? #5; //Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
?? 37:? ldc???? #9; //String ghi
?? 39:? invokevirtual?? #5; //Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
?? 42:? invokevirtual?? #7; //Method java/lang/StringBuilder.toString:()Ljava/lang/String;
?? 45:? invokevirtual?? #10; //Method java/io/PrintStream.println:(Ljava/lang/String;)V
?? 48:? return

}

實際這里的拼接用的是StringBuilder.append。情況沒想的這么糟糕，而且1000次字符串拼接的開銷都比不上一次遠程調用的開銷大，與其想著從這里擠性能，還不如去優化遠程調用和數據庫訪問。

?

第二點，同樣用實驗來做說明，這里對比了使用輔助類，使用isInfoEnabled判斷和不使用判斷的情況，日志級別為INFO，另外再加了使用輔助類，使用isDebugEnabled判斷和不使用判斷的情況，都是循環輸出20萬次，每次的拼接在最后都加了些運算：

Java代碼??

public?class?LogDemo?{??

????private?static?final?Logger?logger?=?LoggerFactory.getLogger(LogDemo.class);??

??

????public?static?void?main(String[]?args)?{??

????????Profiler.start();??

??

????????Profiler.enter("Ignore");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????LogUtil.info(logger,?"test"?+?"test"?+?i?+?i*2);??

????????}??

????????Profiler.release();??

??????????

????????Profiler.enter("InfoUtil");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????LogUtil.info(logger,?"test1"?+?"test2"?+?i?+?i*2);??

????????}??

????????Profiler.release();??

??

????????Profiler.enter("isInfoEnabled");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????if?(logger.isInfoEnabled())?{??

????????????????logger.info("test3"?+?"test4"?+?i?+?i*2);??

????????????}??

????????}??

????????Profiler.release();??

??

????????Profiler.enter("info");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????logger.info("test5"?+?"test6"?+?i?+?i*2);??

????????}??

????????Profiler.release();??

??????????

????????Profiler.enter("DebugUtil");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????LogUtil.debug(logger,?"test7"?+?"test8"?+?i?+?i*2);??

????????}??

????????Profiler.release();??

??

????????Profiler.enter("isDebugEnabled");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????if?(logger.isDebugEnabled())?{??

????????????????logger.debug("test9"?+?"test0"?+?i?+?i*2);??

????????????}??

????????}??

????????Profiler.release();??

??

????????Profiler.enter("debug");??

????????for?(int?i?=?0;?i?<?200000;?i++)?{??

????????????logger.debug("tes1"?+?"tes2"?+?i?+?i*2);??

????????}??

????????Profiler.release();??

??

????????Profiler.release();??

????????System.out.println(Profiler.dump());??

????}??

}??

（ 說明：這里的Profiler類是個工具類，作用是記錄調用的時間；代碼有截取；第一個循環主要是預熱一下，不在統計范圍內）

?

經過了幾次測試，結果如下：

實驗結果 +---14,766 [15,171ms, 26%, 26%] - InfoUtil
+---29,937 [14,187ms, 24%, 24%] - isInfoEnabled
+---44,124 [13,938ms, 24%, 24%] - info
+---58,062 [31ms, 0%, 0%] - DebugUtil
+---58,093 [16ms, 0%, 0%] - isDebugEnabled
`---58,109 [46ms, 0%, 0%] - debug

+---14,968 [14,656ms, 25%, 25%] - InfoUtil
+---29,624 [14,141ms, 24%, 24%] - isInfoEnabled
+---43,765 [14,265ms, 25%, 25%] - info
+---58,030 [47ms, 0%, 0%] - DebugUtil
+---58,077 [0ms] - isDebugEnabled
`---58,077 [47ms, 0%, 0%] - debug

+---14,999 [14,922ms, 26%, 26%] - InfoUtil
+---29,921 [14,093ms, 24%, 24%] - isInfoEnabled
+---44,014 [14,219ms, 24%, 24%] - info
+---58,233 [47ms, 0%, 0%] - DebugUtil
+---58,280 [0ms] - isDebugEnabled
`---58,280 [47ms, 0%, 0%] - debug

+---14,656 [14,812ms, 26%, 26%] - InfoUtil
+---29,468 [14,344ms, 25%, 25%] - isInfoEnabled
+---43,812 [13,890ms, 24%, 24%] - info
+---57,702 [31ms, 0%, 0%] - DebugUtil
+---57,733 [16ms, 0%, 0%] - isDebugEnabled
`---57,749 [47ms, 0%, 0%] - debug

+---16,219 [16,719ms, 25%, 25%] - InfoUtil
+---32,938 [17,703ms, 27%, 27%] - isInfoEnabled
+---50,641 [15,157ms, 23%, 23%] - info
+---65,798 [47ms, 0%, 0%] - DebugUtil
+---65,845 [0ms] - isDebugEnabled
`---65,845 [47ms, 0%, 0%] - debug

（數據說明：第一列為開始計時的時間點，[]內為時間及統計，15,171ms為該階段的具體耗時，后面的百分比是該階段耗時在這個統計內所占的百分比）

?

?對上述數據分析后，可以得到這樣的結論：

日志輸出前的判斷確實有效，但效果甚微

在日志級別較低，不會輸出的情況下，日志的耗時基本可以忽略?，20萬次的調用耗時在50ms內

在日志級別滿足輸出要求時，3種方法差別不大

針對第3條再做些補充說明，日志輸出大的開銷應該在IO上，計算應該不會很多，也不該很多，如果存在大量的運算請自己考慮下是不是有問題；既然是確認要輸出的日志，那增加判斷其實是種浪費，雖然這種判斷的開銷可以忽略。

?

綜上所述，個人建議在日常系統中無需對日志增加isInfoEnabled判斷，想通過這種處理來優化效果的作用不會很明顯，還是把精力從日志移到數據庫和遠程調用上效果更好些。?（特殊情況下，如果在日志中有復雜的操作，可以酌情考慮，但個人不傾向于復雜的日志）

from:?http://digitalsonic.iteye.com/blog/700891

總結

以上是生活随笔為你收集整理的isInfoEnabled究竟多有用？的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。