2010-02-27 346 views
14

在日誌系統中,每個日誌輸出用的方法的輔助類如這個做一個Thread.getStackTrace()有多昂貴?

public void debug(String message) { 
    Logger logger = Logger.getLogger(getCallingClass()); 
    logger.debug(message); 
} 
... 
public Class getCallingClass() { 
/* 
Calls Thread.getStackTrace() and back traces until the class on the stack trace 
!= this.getClass(). 
*/ 
    return classFound; 
} 

這種運行需要多少費用,可能它有顯著的性能命中?

回答

8

是的,有一些開銷這一號召,但在所有的情形產生,你會做這樣的事情:

public static boolean DEBUG_ON = true; //change this before your production build 

然後,

public void debug(String message){ 
    if(DEBUG_ON){ 
    //stack code here 
    } 

} 

這將導致你不要在你的真實代碼中受到打擊。

即便如此,對於異常,您將在生產版本中引發整個堆棧跟蹤異常。請注意,如果您使用的是體面的日誌記錄子系統,他們可能已經根據日誌記錄級別做了一些事情(在我們的日誌系統中,取決於級別,debug()基本上是沒有操作的)。 Log4j和其他人有不同的處理方法。

最後,我會說:不要擔心它,直到它被證明是一個真正的性能問題。過早優化是所有邪惡的根源:)

+1

而不是使用布爾標誌這種情況可以使用記錄器。isDebugEnabled() – Inv3r53 2010-02-27 15:37:03

+1

更好的方法是使用預處理指令。 – Orentet 2010-02-27 15:38:58

+0

這對兩者都有好處。使用靜態最終布爾值,編譯器將只刪除if()語句中的任何內容,因此它就像預處理器指令;) – Kylar 2010-02-27 16:04:24

4

從我記得,使用Thread.getStackTrace()有一些影響 - 尤其是對於大堆棧(例如在服務器端或J2EE情況下使用時)。你可以嘗試Throwable.getStackTrace()以獲得更好的性能。

無論如何,定期調用這些函數(而不是在異常情況下這樣做)會影響您的應用程序。

+0

我懷疑新的'Throwable()。getStackTrace()'是否不僅僅是調用'Thread.getStackTrace()'。 – 2010-02-27 19:41:25

+6

@SoftwareMonkey實際上它確實:Throwable.fillInStackTrace()可以利用知道它正在檢查調用該方法的同一線程的堆棧,而Thread.getStackTrace()必須是線程安全的並且更加昂貴。見http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6375302 – 2011-12-08 23:32:01

+0

@大衛:很高興知道,謝謝。 – 2011-12-09 01:15:27

6

它看起來像獲取當前線程(及其關聯的ID)並不昂貴,但獲取當前線程和它的堆棧跟蹤是。新的throwable()。getStackTrace()模式似乎比線程的堆棧跟蹤模式快得多。

另外,注意:這個基準測試幾乎沒有堆棧深度,因爲它只是一個主要的方法,所以在服務器環境中這個懲罰會變得更重。

基準測試結果:

簡單的循環,用了2毫秒

獲取當前線程花了10毫秒

獲取堆棧跟蹤拿了29564毫秒

獲取拋出的堆棧跟蹤了19910毫秒

代碼:

int trials = 10_000_000; 

    long start = System.currentTimeMillis(); 

    long a = 1; 
    for (int i = 0; i < trials; i += 1) { 
     a += 1; 
    } 

    long duration = System.currentTimeMillis() - start; 
    System.out.println("Simple loop took " + duration + " ms"); 

    start = System.currentTimeMillis(); 

    a = 1; 
    for (int i = 0; i < trials; i += 1) { 
     a += 1; 
     Thread.currentThread().getId(); 
    } 

    duration = System.currentTimeMillis() - start; 
    System.out.println("Getting current thread took " + duration + " ms"); 

    start = System.currentTimeMillis(); 

    a = 1; 
    for (int i = 0; i < trials; i += 1) { 
     a += 1; 
     Thread.currentThread().getStackTrace(); 
    } 

    duration = System.currentTimeMillis() - start; 
    System.out.println("Getting stack trace took " + duration + " ms"); 

      start = System.currentTimeMillis(); 

    a = 1; 
    for (int i = 0; i < trials; i += 1) { 
     a += 1; 
     (new Throwable()).getStackTrace(); 
    } 

    duration = System.currentTimeMillis() - start; 
    System.out.println("Getting throwable stack trace took " + duration + " ms"); 
+0

,我會說currentThread是負責區別 – njzk2 2012-11-14 16:42:37

+2

這個基準是打破。 javac/JVM會將其優化到第一個和第二個循環被完全刪除的程度。另外,millis不能在這裏使用。 – Roman 2014-08-05 11:01:37

+3

「獲取堆棧跟蹤花費了29564毫秒」是一個荒謬的說法;測試代碼表明花了2,900 **納米*秒。另外@Roman完全正確地關於優化改變結果。 – gerardw 2015-07-27 13:35:53

0

現在有了JDK 9 & 10,可以使用StalkWalker,這不是一個昂貴的調用。

private void invoke006() { 
     var stack = StackWalker.getInstance(StackWalker.Option.SHOW_HIDDEN_FRAMES).walk((s) -> s.collect(Collectors.toList())); 
     stack.forEach(stackFrame -> { 
      if (stackFrame.getMethodName().equals("masterInvoker")) { 
       System.err.println("master called !!"); 
       System.err.println(StackWalker.getInstance().walk((s) -> s.collect(Collectors.toList())).get(0).getMethodName() + ", line: " + StackWalker.getInstance().walk((s) -> s.collect(Collectors.toList())).get(0).getLineNumber()); 
      } 
     }); 
    }