最近经常做线上问题的排查，而排查问题用得最多的方式是查看日志，但是在现有系统中，各种无关日志穿行其中，导致我没办法快速的找出用户在一次请求中所有的日志。
我们没办法快速定位用户在一次请求中对应的所有日志，或者说是定位某个用户操作的所有日志，那是因为我们在输出的日志的时候没把请求的唯一标示或者说是用户身份标示输出到我们的日志中，导致我们没办法根据一个请求或者用户身份标示来做日志的过滤。所以我们在记录日志的是后把请求的唯一标示（sessionId）或者身份标示（userId） 记录到日志中这个问题就可以得到很好的解决了。
在每次请求的时候，获取到请求的sessionId（或者自己生成一个伪sessionId），并在每次输出log的时候将这个sessionId输出到日志中。这个方式实现简单，代码侵入型强，每次输出都会多输出一个sessionId参数，工作量大，但是可控粒度高。
我们使用Logback的MDC机制，日志模板中加入sessionId格式。在日志输出格式中指定输出sessionId。如：
%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] -%5p ${PID:-} [%15.15t] %-40.40logger{39} : %m%n
这种方式工作量小，代码侵入小，易扩展，但是可控粒度低。
方案说明
第一种方案很简单，也很容易实现，就是在输出日志的时候多输出一个参数，如：
logger.info("sessionId: {}, message: {}", sessionId, "日志信息");
我们这里主要说一下第二种方式的实现。
实现思路，这里以Spring MVC为例：
新建一个日志拦截器，在拦截所有请求，在处理请求前将sessionId放到MDC中，在处理完请求后清除MDC的内容。这里就解决了80%的问题。
在原来版本中新起线程时MDC会自动将父线程的MDC内容复制给子线程，因为MDC内部使用的是InheritableThreadLocal，但是因为性能问题在最新的版本中被取消了，所以子线程不会自动获取到父线程的MDC内容。官方建议我们在父线程新建子线程之前调用MDC.getCopyOfContextMap()方法将MDC内容取出来传给子线程，子线程在执行操作前先调用MDC.setContextMap()方法将父线程的MDC内容设置到子线程。
设置日志输出格式
%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] -%5p ${PID:-} [%15.15t] %-40.40logger{39} : %m%n
拦截器 LogInterceptor
package com.xiaolyuh.interceptors;
import org.slf4j.MDC;
import org.springframework.web.servlet.ModelAndView;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;
* 日志拦截器组件，在输出日志中加上sessionId
* @author yuhao.wang3
public class LogInterceptor extends HandlerInterceptorAdapter {
* 会话ID
private final static String SESSION_KEY = "sessionId";
@Override
public void afterCompletion(HttpServletRequest arg0, HttpServletResponse arg1, Object arg2, Exception arg3)
throws Exception {
// 删除SessionId
MDC.remove(SESSION_KEY);
@Override
public void postHandle(HttpServletRequest arg0, HttpServletResponse arg1,
Object arg2, ModelAndView arg3) throws Exception {
@Override
public boolean preHandle(HttpServletRequest request,
HttpServletResponse response, Object handler) throws Exception {
// 设置SessionId
String token = UUID.randomUUID().toString().replace("-", "");
MDC.put(SESSION_KEY, token);
return true;
注册拦截器
* WEB MVC配置类
* @author yuhao.wang3
@Configuration
public class WebMvcConfigurer extends WebMvcConfigurerAdapter {
* 把我们的拦截器注入为bean
* @return
@Bean
public HandlerInterceptor logInterceptor() {
return new LogInterceptor();
* 注册拦截器
* @param registry
@Override
public void addInterceptors(InterceptorRegistry registry) {
// addPathPatterns 用于添加拦截规则, 这里假设拦截 /url 后面的全部链接
// excludePathPatterns 用户排除拦截
registry.addInterceptor(logInterceptor()).addPathPatterns("/**");
super.addInterceptors(registry);
扩展ThreadPoolTaskExecutor线程池
扩展ThreadPoolTaskExecutor线程池的主要目的是实现将父线程的MDC内容复制给子线程。
package com.xiaolyuh.utils;
import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import java.util.Map;
* 这是{@link ThreadPoolTaskExecutor}的一个简单替换，可以在每个任务之前设置子线程的MDC数据。
* 在记录日志的时候，一般情况下我们会使用MDC来存储每个线程的特有参数，如身份信息等，以便更好的查询日志。
* 但是Logback在最新的版本中因为性能问题，不会自动的将MDC的内存传给子线程。所以Logback建议在执行异步线程前
* 先通过MDC.getCopyOfContextMap()方法将MDC内存获取出来，再传给线程。
* 并在子线程的执行的最开始调用MDC.setContextMap(context)方法将父线程的MDC内容传给子线程。
* https://logback.qos.ch/manual/mdc.html
* @author yuhao.wang3
public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
* 所有线程都会委托给这个execute方法，在这个方法中我们把父线程的MDC内容赋值给子线程
* https://logback.qos.ch/manual/mdc.html#managedThreads
* @param runnable
@Override
public void execute(Runnable runnable) {
// 获取父线程MDC中的内容，必须在run方法之前，否则等异步线程执行的时候有可能MDC里面的值已经被清空了，这个时候就会返回null
Map<String, String> context = MDC.getCopyOfContextMap();
super.execute(() -> run(runnable, context));
* 子线程委托的执行方法
* @param runnable {@link Runnable}
* @param context 父线程MDC内容
private void run(Runnable runnable, Map<String, String> context) {
// 将父线程的MDC内容传给子线程
MDC.setContextMap(context);
try {
// 执行异步操作
runnable.run();
} finally {
// 清空MDC内容
MDC.clear();
扩展Hystrix
扩展Hystrix线程池隔离支持日志链路跟踪
* Hystrix线程池隔离支持日志链路跟踪
* @author yuhao.wang3
public class MdcHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy {
@Override
public <T> Callable<T> wrapCallable(Callable<T> callable) {
return new MdcAwareCallable(callable, MDC.getCopyOfContextMap());
private class MdcAwareCallable<T> implements Callable<T> {
private final Callable<T> delegate;
private final Map<String, String> contextMap;
public MdcAwareCallable(Callable<T> callable, Map<String, String> contextMap) {
this.delegate = callable;
this.contextMap = contextMap != null ? contextMap : new HashMap();
@Override
public T call() throws Exception {
try {
MDC.setContextMap(contextMap);
return delegate.call();
} finally {
MDC.clear();
配置Hystrix@Configuration
public class HystrixConfig {
//用来拦截处理HystrixCommand注解
@Bean
public HystrixCommandAspect hystrixAspect() {
return new HystrixCommandAspect();
@PostConstruct
public void init() {
HystrixPlugins.getInstance().registerConcurrencyStrategy(new MdcHystrixConcurrencyStrategy());
Logback配置
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<property name="CONSOLE_LOG_PATTERN"
value="${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} [%X{sessionId}] %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
<property name="FILE_LOG_PATTERN"
value="${FILE_LOG_PATTERN:-%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 -->
<discardingThreshold>0</discardingThreshold>
<!-- 更改默认的队列的深度,该值会影响性能.默认值为256 -->
<queueSize>2048</queueSize>
<includeCallerData>true</includeCallerData>
<!-- 添加附加的appender,最多只能添加一个 -->
<appender-ref ref="FILE"/>
</appender>
<logger name="com.xiaolyuh" level="debug" additivity="true"/>
</configuration>
@Service
public class LogService {
Logger logger = LoggerFactory.getLogger(LogService.class);
public void log() {
logger.debug("==============================================");
ThreadTaskUtils.run(() -> run());
FutureTask<String> futureTask = new FutureTask<String>(() -> call());
ThreadTaskUtils.run(futureTask);
try {
logger.debug("===================: {}", futureTask.get());
} catch (Exception e) {
logger.error(e.getMessage(), e);
logger.debug("==============================================");
private String call() {
logger.debug("11111111111");
return "3333";
public void run() {
logger.debug("222222222222222");
日志输出示例
2018-06-02 23:11:02.376 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.376 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-4] com.xiaolyuh.service.LogService : 222222222222222
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-1] com.xiaolyuh.service.LogService : 11111111111
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService : ===================: 3333
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-5] com.xiaolyuh.service.LogService : 222222222222222
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-3] com.xiaolyuh.service.LogService : 11111111111
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService : ===================: 3333
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.728 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.728 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-2] com.xiaolyuh.service.LogService : 222222222222222
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-4] com.xiaolyuh.service.LogService : 11111111111
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService : ===================: 3333
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService : ==============================================
来源：微信公众号 java杂记
SA实战 ·《SpringCloud Alibaba实战》第16章-链路追踪：项目整合Sleuth实现链路追踪 下
SA实战 ·《SpringCloud Alibaba实战》第16章-链路追踪：项目整合Sleuth实现链路追踪
SA实战 ·《SpringCloud Alibaba实战》第16章-链路追踪：项目整合Sleuth实现链路追踪 上
SA实战 ·《SpringCloud Alibaba实战》第16章-链路追踪：项目整合Sleuth实现链路追踪
SpringCloud微服务实战——搭建企业级开发框架（三十三）：整合Skywalking实现链路追踪
Skywalking是由国内开源爱好者吴晟（原OneAPM工程师）开源并提交到Apache孵化器的产品，它同时吸收了Zipkin/Pinpoint/CAT的设计思路，支持非侵入式埋点。是一款基于分布式跟踪的应用程序性能监控系统。另外社区还发展出了一个叫OpenTracing的组织，旨在推进调用链监控的一些规范和标准工作。
1、下载Skywalking，下载地址：https://skywalking.apache.org/downloads/#download-the-latest-versions ,根据需求选择发布的版本，这里我们选择最新发布版v8.4.0 for H2/MySQL/TiDB
Dubbo全链路追踪日志的实现
微服务架构的项目，一次请求可能会调用多个微服务，这样就会产生多个微服务的请求日志，当我们想要查看整个请求链路的日志时，就会变得困难，所幸的是我们有一些集中日志收集工具，比如很热门的ELK，我们需要把这些日志串联起来，这是一个很关键的问题，如果没有串联起来，查询起来很是很困难，我们的做法是在开始请求系统时生成一个全局唯一的id，这个id伴随这整个请求的调用周期，即当一个服务调用另外一个服务的时候，会往下传递，形成一条链路，当我们查看日志时，只需要搜索这个id，整条链路的日志都可以查出来了。
数据链路追踪，我实现了
今天来聊些大家都用得上的东西：数据链路追踪。之前引入了系统的监控来快速定位应用操作系统上的问题，而业务问题呢？在这篇文章中你可以看到用注解的方式打印日志，也能看到简易版的全链路追踪是怎么实现的。
详解ElasticAPM实现微服务的链路追踪（二）
Elastic APM实现链路追踪，首先要引用开源的APMAgent（APM代理），然后将监控的信息发送到APMServer，然后在转存入ElasticSearch，最后有Kibana展示；具体流程如下图所示：
