java多线程使用mdc追踪日志方式 java多线程使用mdc追踪日志方式

多线程使用mdc追踪日志

背景
解决方案
实现
参考

多线程日志追踪

1.问题描述
2. 代理实现日志追踪

多线程使用mdc追踪日志
背景
多线程情况下，子线程的sl4j打印日志缺少traceId等信息，导致定位问题不方便

解决方案

打印日志时添加用户ID、trackId等信息，缺点是每个日志都要手动添加
使用mdc直接拷贝父线程值

实现

// 新建线程时：Map 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}. * * 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. * * Created by jlevy. * Date: 6/14/13 */public class MdcThreadPoolExecutor extends ThreadPoolExecutor {final private boolean useFixedContext; final private Map fixedContext; /*** Pool where task threads take MDC from the submitting thread.*/public static MdcThreadPoolExecutor newWithInheritedMdc(int corePoolSize, int maximumPoolSize, long keepAliveTime,TimeUnit unit, BlockingQueue 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 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 fixedContext, int corePoolSize,int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue workQueue) {return new MdcThreadPoolExecutor(fixedContext, corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue); }private MdcThreadPoolExecutor(Map fixedContext, int corePoolSize, int maximumPoolSize,long keepAliveTime, TimeUnit unit, BlockingQueue workQueue) {super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue); this.fixedContext = fixedContext; useFixedContext = (fixedContext != null); }@SuppressWarnings("unchecked")private Map getContextForTask() {return useFixedContext ? fixedContext : MDC.getCopyOfContextMap(); }/*** All executions will have MDC injected. {@code ThreadPoolExecutor}'s submission methods ({@code submit()} etc.)* all delegate to this.*/@Overridepublic void execute(Runnable command) {super.execute(wrap(command, getContextForTask())); }public static Runnable wrap(final Runnable runnable, final Map context) {return new Runnable() {@Overridepublic 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() {@Overridepublic void run() {//接收到一个requestSystem.out.println("[Thread-"+ Thread.currentThread().getId() +"]开始发起请求"); String[] data = https://www.it610.com/article/{"异常数据","基本数据"}; //创建子线程1，处理异常数据MThread mThread1 = new MThread(new Runnable() {@Overridepublic void run() {System.out.println("[Thread-"+ Thread.currentThread().getId() +"]处理了" + data[0]); }}); 创建子线程2，处理普通数据MThread mThread2 = new MThread(new Runnable() {@Overridepublic 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; } @Overridepublic void run() {r.run(); }}

【java多线程使用mdc追踪日志方式】运行结果如下：

文章图片

一个请求有三个线程，如果有多个请求，运行结果如下：

文章图片

从日志中无法看出他们之间的所属关系（判断不出来他们是否是处理同一个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() {@Overridepublic void run() {//AOP 生成一个traceIdMDC.put("traceId", UUID.randomUUID().toString().replace("-", "")); //接收到一个requestSystem.out.println("[Thread-"+ Thread.currentThread().getId() +"]traceId["+ MDC.get("traceId") +"]开始发起请求"); String[] data = https://www.it610.com/article/{"异常数据","基本数据"}; MThread mThread1 = new MThread(new Runnable() {@Overridepublic void run() {System.out.println("[Thread-"+ Thread.currentThread().getId() +"]traceId["+ MDC.get("traceId") +"]处理了" + data[0]); }}, MDC.getCopyOfContextMap()); MThread mThread2 = new MThread(new Runnable() {@Overridepublic 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 parentThreadMap) {LogProxy logProxy = new LogProxy(r, parentThreadMap); Runnable rProxy = (Runnable) Proxy.newProxyInstance(r.getClass().getClassLoader(), r.getClass().getInterfaces(), logProxy); this.r = rProxy; } @Overridepublic void run() {r.run(); }} //日志代理class LogProxy implements InvocationHandler {private Runnable r; privateMap parentThreadMap; public LogProxy(Runnable r, Map parentThreadMap) {this.r = r; this.parentThreadMap = parentThreadMap; } @Overridepublic 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的信息。
以上为个人经验，希望能给大家一个参考，也希望大家多多支持脚本之家。