日志输出是定位线上问题的重要手段。但是服务大量并发的情况下,我们很难获取单次请求的完整上下文调用链。可能有同学会想到 tomcat线程名、线程号,但是tomcat线程池能够复用线程。还可能有同学想到程序入口生成一个UUID传递给上下文使用,这种类方式能够解决准确获取调用链,但是当我们代码逻辑较为复杂时,难么这种方式代码侵入性就比较高、历史代码改动也比较大。那么如何精确、优雅的获取调用链呢?
对于logback日志框架比较熟悉的同学就会知道,logback中有一个 MDC (Mapped Diagnostic Context)类,可以自定义参数存放到里面,并在logback.xml输出格式中输出自定义参数变量。
下面我们将简单介绍logback集成方式、MDC的源码分析、异步子线程traceID的传递。
logback集成方式:
<!--控制台日志--> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <!-- %d表示日期时间 %-5level:级别从左显示5个字符宽度 %thread表示线程名 %mdc{MSGID} 自定义消息唯一标识,用于跨系统的日志追踪 %X{traceId} 自定义traceId %logger{50} 表示logger名字最长50个字符,否则按照句点分割 %file 输出执行记录记录的java源文件名 %method 输出执行记录记录的java源文件方法名 %line 输出执行日志记录的java源文件行号 %msg:日志消息 %n是换行符 --> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %thread [%mdc{MSGID}] %X{traceId} %logger{50} %file:%method:%line - %msg%n</pattern> </encoder> </appender> |
(一)基于Filter、HandlerInterceptor过滤器方式
import org.apache.log4j.Logger; import javax.servlet.http.HttpServletRequest; /** @Override @Override } @Override |
import com.demo.test.util.UUIDUtils; /** /** public static String get() { /** |
<mvc:interceptors> <mvc:interceptor> <mvc:mapping path="/demo/**" /> <bean class="com.test.demo.intercept.LoggerInterceptor"/> </mvc:interceptor> </mvc:interceptors> |
添加之前: 添加之后: |
(二)基于Spring AOP切面方式
<!--aop功能开启--> <!--<aop:aspectj-autoproxy/>--> |
import java.lang.annotation.*; @Documented } |
import com.demo.test.util.UUIDUtils; @Aspect public static Logger logger = LoggerFactory.getLogger(TraceIDAscept.class); @Pointcut("@annotation(com.demo.annon.TraceID)") //针对带有注解 @TraceIDd 的方法 } |
@TraceID @RequestMapping("/demo/test") @ResponseBody ... |
添加之后: 2020-09-08 17:01:17.634 DEBUG http-bio-8090-exec-1 [] com.test.demo.AppController 520f60db915e4ee5b31521886191530b - 终端请求参数: 2020-09-08 17:01:17.660 DEBUG http-bio-8090-exec-1 [] com.test.demo.AppController 520f60db915e4ee5b31521886191530b - 终端请求app票据信息: 2020-09-08 17:01:17.661 DEBUG http-bio-8090-exec-1 [] com.test.demo.AppController 520f60db915e4ee5b31521886191530b - 应用认证、资源认证...... |
(三)MDC的简单原理
上面介绍完traceId的集成和使用后,我们深入MDC源码一探究竟:
/** import java.util.Map; import org.slf4j.helpers.NOPMDCAdapter; /** static final String NULL_MDCA_URL = "http://www.slf4j.org/codes.html#null_MDCA"; private MDC() { static { /** /** if (mdcAdapter == null) { /** if (mdcAdapter == null) { /** /** /** /** } |
/** import org.slf4j.spi.MDCAdapter; import ch.qos.logback.classic.util.LogbackMDCAdapter; /** /** private StaticMDCBinder() { /** public String getMDCAdapterClassStr() { |
从这个源码中可以看到,MDC的put、get、remove、clear等方法都是基于 MDCAdapter这个类进行操作的,MDCAdapter初始化时通过静态方法块实现了一个 LogbackMDCAdapter子类。我们再看下它的源码:
/** import java.util.Collections; import org.slf4j.spi.MDCAdapter; /** // The internal map is copied so as // We wish to avoid unnecessarily copying of the map. To ensure // We no longer use CopyOnInheritThreadLocal in order to solve LBCLASSIC-183 private static final int WRITE_OPERATION = 1; // keeps track of the last operation performed private Integer getAndSetLastOperation(int op) { private boolean wasLastOpReadOrNull(Integer lastOp) { private Map<String, String> duplicateAndInsertNewMap(Map<String, String> oldMap) { copyOnThreadLocal.set(newMap); /** Map<String, String> oldMap = copyOnThreadLocal.get(); if (wasLastOpReadOrNull(lastOp) || oldMap == null) { /** Integer lastOp = getAndSetLastOperation(WRITE_OPERATION); if (wasLastOpReadOrNull(lastOp)) { /** /** /** /** if (map != null) { /** public void setContextMap(Map<String, String> contextMap) { Map<String, String> newMap = Collections.synchronizedMap(new HashMap<String, String>()); // the newMap replaces the old one for serialisation's sake |
从上面可以看出,所有的操作都是基于ThreadLocal<Map<String, String>> copyOnThreadLocal进行保存数据。ThreadLocal而是一个线程内部的存储类,可以在指定线程内存储数据,数据存储以后,只有指定线程可以得到存储数据。每一个线程读取的变量是对应的互相独立的。通过get和set方法就可以得到当前线程对应的值。这样既可保证一个traceID在整个链路中是惟一的,不会出现并发线程安全问题。
附录:
关于多线程TraceId传递的一种实现方式:
import java.util.Map; import com.demo.test.intercept.LoggerTools; import com.google.common.base.Strings; /** @Override |
即把主线程的ThreadLocal中的Map<String,String>传递给子线程,并设置到子线程的ThreadLocal当中。这样子线程直接也能打印出调用链执行的数据了。