java多線程使用mdc追蹤日志方式

Posted on by

多線程使用mdc追蹤日志

背景

多線程情況下，子線程的sl4j打印日志缺少traceId等信息，導致定位問題不方便

解決方案

  • 打印日志時添加用戶ID、trackId等信息，缺點是每個日志都要手動添加
  • 使用mdc直接拷貝父線程值

實現

// 新建線程時：
Map<String, String> mdcContextMap = MDC.getCopyOfContextMap()
// 子線程運行時：
if(null != mdcContextMap){
    MDC.setContextMap(mdcContextMap);
}
// 銷毀線程時
MDC.clear();

參考

import org.slf4j.MDC;
import java.util.Map;
import java.util.concurrent.*;
/**
 * A SLF4J MDC-compatible {@link ThreadPoolExecutor}.
 * <p/>
 * In general, MDC is used to store diagnostic information (e.g. a user's session id) in per-thread variables, to facilitate
 * logging. However, although MDC data is passed to thread children, this doesn't work when threads are reused in a
 * thread pool. This is a drop-in replacement for {@link ThreadPoolExecutor} sets MDC data before each task appropriately.
 * <p/>
 * Created by jlevy.
 * Date: 6/14/13
 */
public class MdcThreadPoolExecutor extends ThreadPoolExecutor {
    final private boolean useFixedContext;
    final private Map<String, Object> fixedContext;
    /**
     * Pool where task threads take MDC from the submitting thread.
     */
    public static MdcThreadPoolExecutor newWithInheritedMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                            TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(null, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }
    /**
     * Pool where task threads take fixed MDC from the thread that creates the pool.
     */
    @SuppressWarnings("unchecked")
    public static MdcThreadPoolExecutor newWithCurrentMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,
                                                          TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(MDC.getCopyOfContextMap(), corePoolSize, maximumPoolSize, keepAliveTime, unit,
                workQueue);
    }
    /**
     * Pool where task threads always have a specified, fixed MDC.
     */
    public static MdcThreadPoolExecutor newWithFixedMdc(Map<String, Object> fixedContext, int corePoolSize,
                                                        int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                                        BlockingQueue<Runnable> workQueue) {
        return new MdcThreadPoolExecutor(fixedContext, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }
    private MdcThreadPoolExecutor(Map<String, Object> fixedContext, int corePoolSize, int maximumPoolSize,
                                  long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
        this.fixedContext = fixedContext;
        useFixedContext = (fixedContext != null);
    }
    @SuppressWarnings("unchecked")
    private Map<String, Object> getContextForTask() {
        return useFixedContext ? fixedContext : MDC.getCopyOfContextMap();
    }
    /**
     * All executions will have MDC injected. {@code ThreadPoolExecutor}'s submission methods ({@code submit()} etc.)
     * all delegate to this.
     */
    @Override
    public void execute(Runnable command) {
        super.execute(wrap(command, getContextForTask()));
    }
    public static Runnable wrap(final Runnable runnable, final Map<String, Object> context) {
        return new Runnable() {
            @Override
            public void run() {
                Map previous = MDC.getCopyOfContextMap();
                if (context == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(context);
                }
                try {
                    runnable.run();
                } finally {
                    if (previous == null) {
                        MDC.clear();
                    } else {
                        MDC.setContextMap(previous);
                    }
                }
            }
        };
    }
}

多線程日志追蹤

主要目的是記錄工作中的一些編程思想和細節，以便後來查閱。

1.問題描述

由於項目中設計高並發內容，涉及到一個線程創建多個子線程的情況。 那麼，如何跟蹤日志，識別子線程是由哪個主線程創建的，屬於哪個request請求。

例如， 在現有項目中，一個設備信息上傳的請求（包括基本數據和異常數據兩種數據），然後主線程創建兩個子線程，來處理基本數據和異常數據。

簡化代碼如下：

public class mainApp {
    public static void main(String[] args) {
        Thread t = new Thread(new Runnable() {
            @Override
            public void run() {
                //接收到一個request
                System.out.println("[Thread-"+ Thread.currentThread().getId() +"]開始發起請求");
                String[] data = {"異常數據","基本數據"};
                //創建子線程1，處理異常數據
                MThread mThread1 = new MThread(new Runnable() {
                    @Override
                    public void run() {
                        System.out.println("[Thread-"+ Thread.currentThread().getId() +"]處理瞭" + data[0]);
                    }
                });
                創建子線程2，處理普通數據
                MThread mThread2 = new MThread(new Runnable() {
                    @Override
                    public void run() {
                        System.out.println("[Thread-"+ Thread.currentThread().getId() +"]處理瞭"  + data[1]);
                    }
                });
                new Thread(mThread1).start();
                new Thread(mThread2).start(); 
            }
        });
        t.start();
    }
}
 
class MThread implements Runnable { 
    private Runnable r; 
    public MThread(Runnable r) {
        this.r = r;
    }
 
    @Override
    public void run() {
        r.run();
    }
}

運行結果如下：

一個請求有三個線程，如果有多個請求，運行結果如下：

從日志中無法看出他們之間的所屬關系（判斷不出來他們是否是處理同一個request請求的）。如果某一個線程出現問題，我們也很難快速定位是哪個請求的處理結果。

2. 代理實現日志追蹤

因此，我們使用MDC來在日志中增加traceId（同一個請求的多個線程擁有同一個traceId）。

思路如下：

1. 在request進來的時候， 利用AOP為每個request創建一個traceId（保證每個request的traceId不同， 同一個request的traceId相同）

2. 創建子線程的時候， 將traceId通過動態代理的方式，傳遞到子線程中

public class mainApp {
    public static void main(String[] args) {
        Runnable runnable = new Runnable() {
            @Override
            public void run() {
                //AOP 生成一個traceId
                MDC.put("traceId", UUID.randomUUID().toString().replace("-", ""));
                //接收到一個request
                System.out.println("[Thread-"+ Thread.currentThread().getId() +"]traceId["+ MDC.get("traceId") +"]開始發起請求");
                String[] data = {"異常數據","基本數據"};
 
                MThread mThread1 = new MThread(new Runnable() {
                    @Override
                    public void run() {
                        System.out.println("[Thread-"+ Thread.currentThread().getId() +"]traceId["+ MDC.get("traceId") +"]處理瞭" + data[0]);
                    }
                }, MDC.getCopyOfContextMap());
                MThread mThread2 = new MThread(new Runnable() {
                    @Override
                    public void run() {
                        System.out.println("[Thread-"+ Thread.currentThread().getId() +"]traceId["+ MDC.get("traceId") +"]處理瞭"  + data[1]);
                    }
                }, MDC.getCopyOfContextMap());
                new Thread(mThread1).start();
                new Thread(mThread2).start(); 
            }
        };
        new Thread(runnable).start();
        new Thread(runnable).start();
    }
}
 
class MThread implements Runnable { 
    private Runnable r; 
    public MThread(Runnable r, Map<String, String> parentThreadMap) {
        LogProxy logProxy = new LogProxy(r, parentThreadMap);
        Runnable rProxy = (Runnable) Proxy.newProxyInstance(r.getClass().getClassLoader(), r.getClass().getInterfaces(), logProxy);
        this.r = rProxy;
    }
 
    @Override
    public void run() {
        r.run();
    }
}
 
//日志代理
class LogProxy implements InvocationHandler {
    private Runnable r;
    private  Map<String, String> parentThreadMap;
    public LogProxy(Runnable r, Map<String, String> parentThreadMap) {
        this.r = r;
        this.parentThreadMap = parentThreadMap;
    }
 
    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        if (method.getName().equals("run")) {
            MDC.setContextMap(parentThreadMap);
        }
        return method.invoke(r, args);
    }
}

運行結果如下：

兩個請求， 同一個請求的traceId相同，不同請求的traceId不同。 完美實現多線程的日志追蹤。

實際WEB項目中，隻需要在logback日志配置文件中，

logging.pattern.console參數增[%X{traceId}]即可在LOGGER日志中打印traceId的信息。

以上為個人經驗，希望能給大傢一個參考，也希望大傢多多支持WalkonNet。

推薦閱讀：