isInfoEnabled究竟多有用?
前段時間,公司里組織了一次代碼檢查,其中有一條檢查項讓我有些費解:
所有INFO和DEBUG級別的日志,必須加上isInfoEnabled和isDebugEnabled的判斷。理由是大量的不輸出的日志對性能會有影響(日志中存在字符串拼接)。如果說只是DEBUG的加上,我也就認了,可是在系統中寫成INFO的日志如果不輸出,那還寫它干嘛,我就是想看到關鍵路徑的日志。而且在大多數日志上加上這么一個判斷真的很難看。。。
?
所謂上有政策,下有對策,于是有人開始寫一些包裝了判斷的輔助類,當中用這樣的代碼(截取):
Java代碼??但這樣的代碼真的就能解決問題了嗎?答案是“不能”!字符串拼接還存在。
?
那讓我們分兩個部分來看一下這個問題:
關于第一個問題,String的拼接是不修改原來的字符串的,而是創建一個新的String對象,道理上是這么說的,我們也該這么理解。但Java編譯器并不傻,實際情況是怎么樣的呢,它會做些優化。請看如下代碼:
Java代碼??在編譯后,通過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代碼??( 說明:這里的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為該階段的具體耗時,后面的百分比是該階段耗時在這個統計內所占的百分比)
?
?對上述數據分析后,可以得到這樣的結論:
針對第3條再做些補充說明,日志輸出大的開銷應該在IO上,計算應該不會很多,也不該很多,如果存在大量的運算請自己考慮下是不是有問題;既然是確認要輸出的日志,那增加判斷其實是種浪費,雖然這種判斷的開銷可以忽略。
?
綜上所述,個人建議在日常系統中無需對日志增加isInfoEnabled判斷,想通過這種處理來優化效果的作用不會很明顯,還是把精力從日志移到數據庫和遠程調用上效果更好些。?(特殊情況下,如果在日志中有復雜的操作,可以酌情考慮,但個人不傾向于復雜的日志)
from:?http://digitalsonic.iteye.com/blog/700891
總結
以上是生活随笔為你收集整理的isInfoEnabled究竟多有用?的全部內容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: Log4j的isdebugEnabled
- 下一篇: Tomcat的安装配置与JavaWeb入