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

更新時(shí)間：2021年09月23日 09:48:14 作者：致林

這篇文章主要介紹了java多線程使用mdc追蹤日志方式，具有很好的參考價(jià)值，希望對(duì)大家有所幫助。如有錯(cuò)誤或未考慮完全的地方，望不吝賜教

多線程使用mdc追蹤日志

背景

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

解決方案

打印日志時(shí)添加用戶ID、trackId等信息，缺點(diǎn)是每個(gè)日志都要手動(dòng)添加
使用mdc直接拷貝父線程值

實(shí)現(xiàn)

// 新建線程時(shí)：
Map<String, String> mdcContextMap = MDC.getCopyOfContextMap()
// 子線程運(yùn)行時(shí)：
if(null != mdcContextMap){
    MDC.setContextMap(mdcContextMap);
}
// 銷毀線程時(shí)
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);
                    }
                }
            }
        };
    }
}

多線程日志追蹤

主要目的是記錄工作中的一些編程思想和細(xì)節(jié)，以便后來查閱。

1.問題描述

由于項(xiàng)目中設(shè)計(jì)高并發(fā)內(nèi)容，涉及到一個(gè)線程創(chuàng)建多個(gè)子線程的情況。那么，如何跟蹤日志，識(shí)別子線程是由哪個(gè)主線程創(chuàng)建的，屬于哪個(gè)request請(qǐng)求。

例如，在現(xiàn)有項(xiàng)目中，一個(gè)設(shè)備信息上傳的請(qǐng)求（包括基本數(shù)據(jù)和異常數(shù)據(jù)兩種數(shù)據(jù)），然后主線程創(chuàng)建兩個(gè)子線程，來處理基本數(shù)據(jù)和異常數(shù)據(jù)。

簡(jiǎn)化代碼如下：

public class mainApp {
    public static void main(String[] args) {
        Thread t = new Thread(new Runnable() {
            @Override
            public void run() {
                //接收到一個(gè)request
                System.out.println("[Thread-"+ Thread.currentThread().getId() +"]開始發(fā)起請(qǐng)求");
                String[] data = {"異常數(shù)據(jù)","基本數(shù)據(jù)"};
                //創(chuàng)建子線程1，處理異常數(shù)據(jù)
                MThread mThread1 = new MThread(new Runnable() {
                    @Override
                    public void run() {
                        System.out.println("[Thread-"+ Thread.currentThread().getId() +"]處理了" + data[0]);
                    }
                });
                創(chuàng)建子線程2，處理普通數(shù)據(jù)
                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();
    }
}

運(yùn)行結(jié)果如下：

一個(gè)請(qǐng)求有三個(gè)線程，如果有多個(gè)請(qǐng)求，運(yùn)行結(jié)果如下：

從日志中無法看出他們之間的所屬關(guān)系（判斷不出來他們是否是處理同一個(gè)request請(qǐng)求的）。如果某一個(gè)線程出現(xiàn)問題，我們也很難快速定位是哪個(gè)請(qǐng)求的處理結(jié)果。

2. 代理實(shí)現(xiàn)日志追蹤

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

思路如下：

1. 在request進(jìn)來的時(shí)候，利用AOP為每個(gè)request創(chuàng)建一個(gè)traceId（保證每個(gè)request的traceId不同，同一個(gè)request的traceId相同）

2. 創(chuàng)建子線程的時(shí)候，將traceId通過動(dòng)態(tài)代理的方式，傳遞到子線程中

public class mainApp {
    public static void main(String[] args) {
        Runnable runnable = new Runnable() {
            @Override
            public void run() {
                //AOP 生成一個(gè)traceId
                MDC.put("traceId", UUID.randomUUID().toString().replace("-", ""));
                //接收到一個(gè)request
                System.out.println("[Thread-"+ Thread.currentThread().getId() +"]traceId["+ MDC.get("traceId") +"]開始發(fā)起請(qǐng)求");
                String[] data = {"異常數(shù)據(jù)","基本數(shù)據(jù)"};
 
                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);
    }
}

運(yùn)行結(jié)果如下：