1. 程式人生 > >通過slf4j/log4j的MDC/NDC 實現日誌追蹤

通過slf4j/log4j的MDC/NDC 實現日誌追蹤

首先介紹下NDC和MDC的區別:

NDC和MDC

NDC(Nested Diagnostic Context)和MDC(Mapped Diagnostic Context)是log4j種非常有用的兩個類,它們用於儲存應用程式的上下文資訊(context infomation),從而便於在log中使用這些上下文資訊。

NDC採用了一個類似棧的機制來push和pop上下文資訊,每一個執行緒都獨立地儲存上下文資訊。比如說一個servlet就可以針對每一個request建立對應的NDC,儲存客戶端地址等等資訊。

當使用的時候,我們要儘可能確保在進入一個context的時候,把相關的資訊使用NDC.push(message);在離開這個context的時候使用NDC.pop()將資訊刪除。另外由於設計上的一些問題,還需要保證在當前thread結束的時候使用NDC.remove()清除記憶體,否則會產生記憶體洩漏的問題。

儲存了上下文資訊之後,我們就可以在log的時候將資訊輸出。在相應的PatternLayout中使用”%x”來輸出儲存的上下文資訊,下面是一個PatternLayout的例子:

%r [%t] %-5p %c{2} %x - %m%n

使用NDC最重要的好處就是,當我們想輸出一些上下文的資訊的時候,不需要讓logger去尋找這些資訊,而只需要在適當的位置進行儲存,然後再配置檔案中修改PatternLayout。在最新的log4j 1.3版本中增加了一個org.apache.log4j.filters.NDCMatch

Filter,用來根據NDC中儲存的資訊接受或拒絕一條log資訊。

        MDC和NDC非常相似,所不同的是MDC內部使用了類似map的機制來儲存資訊,上下文資訊也是每個執行緒獨立地儲存,所不同的是資訊都是以它們的key值儲存在”map”中。相對應的方法,MDC.put(key, value); MDC.remove(key); MDC.get(key); 在配置PatternLayout的時候使用:%x{key}來輸出對應的value。同樣地,MDC也有一個org.apache.log4j.filters.MDCMatchFilter。這裡需要注意的一點,MDC是執行緒獨立的,但是一個子執行緒會自動獲得一個父執行緒MDC的copy。

至於選擇NDC還是MDC要看需要儲存的上下文資訊是堆疊式的還是key/value形式的。

NDC的實現是用hashtable來儲存每個執行緒的stack資訊,這個stack是每個執行緒可以設定當前執行緒的request的相關資訊,然後當前執行緒在處理過程中只要在log4j配置打印出%x的資訊,那麼當前執行緒的整個stack資訊就會在log4j列印日誌的時候也會都打印出來,這樣可以很好的跟蹤當前request的使用者行為功能。

MDC的實現是使用threadlocal來儲存每個執行緒的Hashtable的類似map的資訊,其他功能類似。




在分散式系統或者較為複雜的系統中,我們希望可以看到一個客戶請求的處理過程所涉及到的所有子系統\模組的處理日誌。

     由於slf4j/log4j基本是日誌記錄的標準組件,所以slf4j/log4j成為了我的重點研究物件。

     slf4j/log4j支援MDC,可以實現同一請求的日誌追蹤功能。

     基本思路是:

     實現自定義Filter,在接受到http請求時,計算eventID並存儲在MDC中。如果涉及分散式多系統,那麼向其他子系統傳送請求時,需要攜帶此eventID。

原始碼:https://github.com/athinboy/studyjava.git

其中:

response.setHeader("eventsign", eventsign);很有用,返回的response中,將有httpheader:eventsign:000010x1489108079237

log4j日誌格式配置為:
log4j.appender.stdout.layout.ConversionPattern=%d %logger-%5p - %X{eventid} - %m%n
  在web.xml中配置自定義filter: <!--start  log4jfilter-->
    <filter>
        <filter-name>log4jfilter</filter-name>
        <filter-class>org.fgq.study.log4j.Log4jFilter</filter-class>
        <init-param>
            <param-name>sign</param-name>
            <param-value>000010x</param-value>
        </init-param>
     </filter>
    <filter-mapping>
        <filter-name>log4jfilter</filter-name>
        <url-pattern>/*</url-pattern>
    </filter-mapping>  

    <!--end  log4jfilter-->

doFilterInternal方法:
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        String eventsign;
        if (request.getHeader("eventsign") == null || request.getHeader("eventsign").length() == 0) {
            eventsign = this.sign + String.valueOf(new Date().getTime()); //計算eventID
            logger.error("set eventid:" + eventsign);
        } else {
            eventsign = request.getHeader("eventsign");//從請求端獲取eventsign
            logger.error("get eventid from request:" + eventsign);
        }
        MDC.put("eventid",  eventsign);
        response.setHeader("eventsign", eventsign);
        filterChain.doFilter(request, response);
    }

測試結果:

1、

Request URL:http://localhost:8084/spmvc/index.html
Request Method:GET
Status Code:304 Not Modified
Remote Address:[::1]:8084

Response Headers
Date:Fri, 10 Mar 2017 03:20:01 GMT
ETag:W/"660-1489115626000"
eventsign:000010x1489116001756

伺服器端日誌:
2017-03-10 11:20:01,756 org.fgq.study.log4j.Log4jFilter.doFilterInternal(Log4jFilter.java:59)ogger-ERROR - - set eventid:000010x1489116001756

MDC的一個舉例:

  1. import org.apache.log4j.MDC;  
  2.   
  3. public class ThreadTest extends Thread {  
  4.     private int i ;  
  5.       
  6.     public ThreadTest(){  
  7.     }  
  8.       
  9.     public ThreadTest(int i){  
  10.         this.i = i;  
  11.     }  
  12.       
  13.     public void run(){  
  14.         System.out.println(++i);  
  15.         MDC.put("username", i);  
  16.       
  17.         for (int j = 0; j < 100; j++) {  
  18.             System.out.println("aaa" + i);  
  19.             if(j==10){  
  20.                 try {  
  21.                     this.sleep(1000);  
  22.                 } catch (InterruptedException e) {  
  23.                     e.printStackTrace();  
  24.                 }  
  25.             }  
  26.         }  
  27.         System.out.println("run: " + i + "     "  + MDC.get("username"));  
  28.     }  
  29.       
  30.     public static void main(String args[]) throws InterruptedException{  
  31.         ThreadTest t1 = new ThreadTest(1);  
  32.         t1.start();  
  33.         ThreadTest t2 = new ThreadTest(2);  
  34.         t2.start();  
  35.     }  
  36. }  

執行結果如下:

  1. 2  
  2. 3  
  3. aaa3  
  4. aaa3  
  5. aaa2  
  6. aaa3  
  7. aaa2  
  8. aaa3  
  9. aaa2  
  10. aaa3  
  11. aaa2  
  12. aaa3  
  13. aaa2  
  14. aaa3  
  15. aaa2  
  16. aaa2  
  17. aaa2  
  18. aaa2  
  19. aaa2  
  20. run: 2     2  
  21. aaa3  
  22. aaa3  
  23. aaa3  
  24. run: 3     3  
 從結果中可以看出:程序t1與t2在MDC中的值是沒有相互影響的,確保了多程序下程序之間在MDC存放的值是沒有相互的影響的或者說是無關的(程序t1在MDC中的username的鍵值為2;程序t2在MDC中的username的鍵值為3)。

分析:

  MDC類put方法:

檢視文字列印
  1. public static void put(String key, Object o)  
  2.   {  
  3.     mdc.put0(key, o);  
  4.   }  
  5.   
  6.   private void put0(String key, Object o)  
  7.   {  
  8.     if (this.java1) {  
  9.       return;  
  10.     }  
  11.     Hashtable ht = (Hashtable)((ThreadLocalMap)this.tlm).get();  
  12.     if (ht == null) {  
  13.       ht = new Hashtable(7);  
  14.       ((ThreadLocalMap)this.tlm).set(ht);  
  15.     }  
  16.     ht.put(key, o);  
  17.   }  

結合類java.lang.ThreadLocal<T>及Thread類可以知道,MDC中的put方法其實就是講鍵值對放入一個Hashtable物件中,然後賦值給當前執行緒的ThreadLocal.ThreadLocalMap物件,即threadLocals,這保證了各個執行緒的在MDC鍵值對的獨立性。

下邊為java.lang.ThreadLocal<T>的部分程式碼:

檢視文字列印
  1. public class ThreadLocal<T> {  
  2.       
  3.     public void set(T value) {  
  4.         Thread t = Thread.currentThread();  
  5.         ThreadLocalMap map = getMap(t);  
  6.         if (map != null)  
  7.             map.set(this, value);  
  8.         else  
  9.             createMap(t, value);  
  10.     }  
  11.   
  12.   
  13.     public T get() {  
  14.         Thread t = Thread.currentThread();  
  15.         ThreadLocalMap map = getMap(t);  
  16.         if (map != null) {  
  17.             ThreadLocalMap.Entry e = map.getEntry(this);  
  18.             if (e != null)  
  19.                 return (T)e.value;  
  20.         }  
  21.         return setInitialValue();  
  22.     }  
  23.   
  24.     ThreadLocalMap getMap(Thread t) {  
  25.         return t.threadLocals;  
  26.     }  
  27.       
  28. }  

Thread類的部分程式碼:

檢視文字列印
  1. public class Thread implements Runnable {  
  2.     ThreadLocal.ThreadLocalMap threadLocals = null;  
  3.   
  4.     ......................  
  5.     .........................  
  6.   
  7.     static class ThreadLocalMap { //ThreadLocalMap為Thread類的內部類  
  8.   
  9.     }  
  10. }  

一:MDC介紹

  MDC(Mapped Diagnostic Context,對映除錯上下文)是 log4j 和 logback 提供的一種方便在多執行緒條件下記錄日誌的功能。某些應用程式採用多執行緒的方式來處理多個使用者的請求。在一個使用者的使用過程中,可能有多個不同的執行緒來進行處理。典型的例子是 Web 應用伺服器。當用戶訪問某個頁面時,應用伺服器可能會建立一個新的執行緒來處理該請求,也可能從執行緒池中複用已有的執行緒。在一個使用者的會話存續期間,可能有多個執行緒處理過該使用者的請求。這使得比較難以區分不同使用者所對應的日誌。當需要追蹤某個使用者在系統中的相關日誌記錄時,就會變得很麻煩。

  一種解決的辦法是採用自定義的日誌格式,把使用者的資訊採用某種方式編碼在日誌記錄中。這種方式的問題在於要求在每個使用日誌記錄器的類中,都可以訪問到使用者相關的資訊。這樣才可能在記錄日誌時使用。這樣的條件通常是比較難以滿足的。MDC 的作用是解決這個問題。

  MDC 可以看成是一個與當前執行緒繫結的雜湊表,可以往其中新增鍵值對。MDC 中包含的內容可以被同一執行緒中執行的程式碼所訪問。當前執行緒的子執行緒會繼承其父執行緒中的 MDC 的內容。當需要記錄日誌時,只需要從 MDC 中獲取所需的資訊即可。MDC 的內容則由程式在適當的時候儲存進去。對於一個 Web 應用來說,通常是在請求被處理的最開始儲存這些資料。

二:日誌聚合與分析(摘自:http://www.ibm.com/developerworks/cn/java/j-lo-practicelog/index.html) -- 此部分是為了方便自己查閱,從參考資料中摘出來放到這裡的

在程式中正確的地方輸出合適的日誌訊息,只是合理使用日誌的第一步。日誌記錄的真正作用在於當有問題發生時,能夠幫助開發人員很快的定位問題所在。不過一個實用的系統通常由很多個不同的部分組成。這其中包括所開發的程式本身,也包括所依賴的第三方應用程式。以一個典型的電子商務網站為例,除了程式本身,還包括所依賴的底層作業系統、應用伺服器、資料庫、HTTP 伺服器和代理伺服器和快取等。當一個問題發生時,真正的原因可能來自程式本身,也可能來自所依賴的第三方程式。這就意味著開發人員可能需要檢查不同伺服器上不同應用程式的日誌來確定真正的原因。

日誌聚合的作用就在於可以把來自不同伺服器上不同應用程式產生的日誌聚合起來,存放在單一的伺服器上,方便進行搜尋和分析。在日誌聚合方面,已經有不少成熟的開源軟體可以很好的滿足需求。本文中要介紹的是 logstash,一個流行的事件和日誌管理開源軟體。logstash 採用了一種簡單的處理模式:輸入 -> 過濾器 -> 輸出。logstash 可以作為代理程式安裝到每臺需要收集日誌的機器上。logstash 提供了非常多的外掛來處理不同型別的資料輸入。典型的包括控制檯、檔案和 syslog 等;對於輸入的資料,可以使用過濾器來進行處理。典型的處理方式是把日誌訊息轉換成結構化的欄位;過濾之後的結果可以被輸出到不同的目的地,比如 ElasticSearch、檔案、電子郵件和資料庫等。

Logstash 在使用起來很簡單。從官方網站下載 jar 包並執行即可。在執行時需要指定一個配置檔案。配置檔案中定義了輸入、過濾器和輸出的相關配置。清單 9 給出了一個簡單的 logstash 配置檔案的示例。

清單 9. logstash 配置檔案示例
檢視文字列印
  1. input {   
  2.  file {   
  3.    path => [ "/var/log/*.log""/var/log/messages""/var/log/syslog" ]   
  4.    type => 'syslog'  
  5.  }   
  6. }   
  7.   
  8. output {   
  9.  stdout {   
  10. debug => true   
  11. debug_format => "json"   
  12.  }   
  13. }  

清單 9 中定義了 logstash 收集日誌時的輸入(input)和輸出(output)的相關配置。輸入型別是檔案(file)。每種型別輸入都有相應的配置。對於檔案來說,需要配置的是檔案的路徑。對每種型別的輸入,都需要指定一個型別(type)。該型別用來區分來自不同輸入的記錄。程式碼中使用的輸出是控制檯。配置檔案完成之後,通過