Fenriswolf 程式筆記

奮利斯狼的地盤,小綿羊勿入

Log4j NDC 簡介

在 trace log 時會常遇到一個問題,在 multi-thread 的環境下不同 thread 的 log 交雜
如何區分哪些 log 是屬於同一個 thread 對 debug 會很有幫助
log4j NDC 就是解決這個問題的一帖良藥

NDC 會幫每個 thread 管理一個 stack,透過 push() 和 pop() methods 插入所需要的資訊
顯示的方式就是在 ConversionPattern 加上 %x 的參數,這樣做的好處是可以分離真正要顯示的訊息及額外訊息
也可用不同的 pattern 改變 output

用講的不容易了解 NDC 的好處,下面是一個 NDC 的使用範例
先建立一個多執行緒的程式並用 NDC.push() 加上 thread name

public class Log4jTest {
    public static void main(String[] args) {
        for (int i = 0; i <= 4; i++) {
            Thread t = new Thread(new Log4jRunnable(i));
            t.start();
        }
    }
}

class Log4jRunnable implements Runnable {
    private static Log log = LogFactory.getLog(Log4jRunnable.class);
    private int index;

    public Log4jRunnable(int index) {
        this.index = index;
    }

    @Override
    public void run() {
        NDC.push(Thread.currentThread().getName());        
        log.info("thread " + index + " start");
 
        try {
            Thread.sleep((long)(Math.random() * 100));
        } catch (InterruptedException e) {
        }
        
        log.info("thread " + index + " end");
        NDC.pop();
    }
}

之後是 log4j 的 xml 定義

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"
    debug="false">

    <appender name="Console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <param name="Threshold" value="INFO" />

        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern"
                value="[%x][%d{HH:mm:ss}][%-5p] (%c{1}:%L) : %m%n" />
        </layout>
    </appender>

    <root>
        <appender-ref ref="Console" />
    </root>
</log4j:configuration>

最後是程式執行產生的 log

[Thread-0][20:23:45][INFO ] (Log4jRunnable:29) : thread 0 start
[Thread-2][20:23:45][INFO ] (Log4jRunnable:29) : thread 2 start
[Thread-4][20:23:45][INFO ] (Log4jRunnable:29) : thread 4 start
[Thread-1][20:23:45][INFO ] (Log4jRunnable:29) : thread 1 start
[Thread-2][20:23:45][INFO ] (Log4jRunnable:36) : thread 2 end
[Thread-3][20:23:45][INFO ] (Log4jRunnable:29) : thread 3 start
[Thread-1][20:23:45][INFO ] (Log4jRunnable:36) : thread 1 end
[Thread-0][20:23:45][INFO ] (Log4jRunnable:36) : thread 0 end
[Thread-3][20:23:45][INFO ] (Log4jRunnable:36) : thread 3 end
[Thread-4][20:23:45][INFO ] (Log4jRunnable:36) : thread 4 end

每個 thread 會分別印出 start 及 end 的訊息,由前方的 thread name 可看出來之間配對的關係
這裡在 info() 印出來的 thead index 只是為了驗証,實際上這類的訊息並不是主要的 log 內容

NDC 用 stack 而不是單純的 string 來當做儲存方式,因此可以重複 push 不同的資訊提供一個階層式的 log
例如以下的圖

如果想用 NDC 顯示 classes 執行的順序
可以建立一個 Advice 並經由 spring auto proxy 設定給所有的 beans

public class LogMethodAdvice implements MethodBeforeAdvice,
        AfterReturningAdvice {

    public void before(Method method, Object[] args, Object target)
            throws Throwable {
        if (NDC.getDepth() == 0) {
            NDC.push(target.getClass().getSimpleName());
        } else {
            NDC.push("-> " + target.getClass().getSimpleName());
        }
    }

    public void afterReturning(Object obj, Method method, Object[] args,
            Object target) throws Throwable {
        NDC.pop();
    }
}

這個 Advice 會在每個 method 進入時把 class name 放入 stack,當出 method 後把上一個訊息拿掉

產生的 log 如下

[ServiceA][INFO ] (ServiceA:15) : do something before calling serviceB
[ServiceA -> ServiceB][INFO ] (ServiceB:13) : do something before calling serviceC
[ServiceA -> ServiceB -> ServiceC][INFO ] (ServiceC:11) : do something
[ServiceA -> ServiceD][INFO ] (ServiceD:11) : do something
[ServiceA][INFO ] (ServiceA:20) : do something after calling serviceD

既然有這麼好用的功能,可輸入的資訊隨 developers 來決定
相關的應用也很多,例如以每個 thread 來分析 performance、傳入使用者 id 並搭配相關 log 分析不同的 user 瀏覽網站的習慣等等……
 
 
執行環境
JDK 1.6.0_03
log4j 1.2.14

參考資料
log4j

程式下載
Log4jTest.java
LogMethodAdvice.java

廣告

2012/03/19 - Posted by | Java Tool |

仍無迴響。

發表迴響

在下方填入你的資料或按右方圖示以社群網站登入:

WordPress.com Logo

您的留言將使用 WordPress.com 帳號。 登出 /  變更 )

Google+ photo

您的留言將使用 Google+ 帳號。 登出 /  變更 )

Twitter picture

您的留言將使用 Twitter 帳號。 登出 /  變更 )

Facebook照片

您的留言將使用 Facebook 帳號。 登出 /  變更 )

w

連結到 %s

%d 位部落客按了讚: