一、前言
日常工作中排查线上问题,经常会遇到一些问题:
- 线上系统某次调用异常,是哪笔订单的什么操作造成的?是哪个服务调用的?来自哪台机子?
- 异常订单操作,对数据有哪些造成了影响?
- 用户在某个时段分别进行了哪些操作?
而日趋复杂的分布式系统,
- 微服务
- 分布式中间价:消息队列、分布式缓存、分布式对象存储
- 不同调用:跨机房、跨区域调用、第三方调用
调用链作为排查问题的核心,通过其可以将各类数据关联在一起,提高问题排查能力。
啥是 MDC ?
MDC(Mapped Diagnostic Context) :映射诊断上下文,是 Logback
框架中一个特征。(Logback是 SpringBoot 的默认框架)
- 它可以在日志消息中存储上下文消息,在日志事件之间传播键值。
快速入门
- 在 pom.xml 中添加
logback-classic
依赖
xml
代码解读
复制代码
<dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.2.3</version> </dependency>
- 在
logback.xml
中配置日志信息
xml
代码解读
复制代码
<configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %mdc - %msg%n</pattern> </encoder> </appender> <root level="debug"> <appender-ref ref="STDOUT" /> </root> </configuration>
<PatternLayout pattern="[%date{yyyy-MM-dd HH:mm:ss,SSS}] [%level] [%C{1}:%line] [%thread] [%traceId] -- %mdc{operator} %mdc{request} %m%n"/>
- 通过
MDC
设置key
整理了一份好像面试笔记包括了:Java面试、Spring、JVM、MyBatis、Redis、MySQL、并发编程、微服务、Linux、Springboot、SpringCloud、MQ、Kafka 面试专题
需要全套面试笔记【点击此处即可】免费获取
java
代码解读
复制代码
@Component public class RequestInterceptor implements HandlerInterceptor { @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { String userId = request.getHeader("traceId"); MDC.put("traceId", traceId); return true; } @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { MDC.remove("traceId"); } }
啥是traceId ?
traceId
:用于标识某一次具体的请求ID。通过 traceId 来将一个请求在各个服务器上的调用日志串联起来。
- traceId 一般由接收请求经过的第一个服务产生。
traceId
与 spanId
区别:
traceId
是用于 串联 某一次请求在系统中经过的所有路径spanId
是用于 区分 系统不同服务之间调用的先后关系
traceId 生成规则
SkyWalking
里TraceId
组成规则:
这里我们参考阿里的鹰眼组件的 TraceId 生成的规则。
生成规则如下: 服务器 IP + ID 产生的时间 + 自增序列 + 当前进程号 ,比如:
- 0ad1348f1403169275002100356696
- 共 30 位
0 | 1 | 2 | 3 | 4 | 5 | 6 | 7 | 8 | 9 | 10 | 11 | 12 | 13 | 14 | 15 | 16 | 17 | 18 | 19 | 20 | 21 | 22 | 23 | 24 | 25 | 26 | 27 | 28 | 29 |
---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
服务器IP,十六进制:0ad1348f | 时间戳,1403169275002 | 自增序列,1003 | 当前进程ID |
- 前8位:0-7,产生 TraceId 的机器的 IP,这是一个十六进制的数字,每两位代表 IP 中的一段。
-
- 按每两位转成 10 进制即可得到常见的 IP 地址表示方式
10.209.52.143
- 按每两位转成 10 进制即可得到常见的 IP 地址表示方式
- 再13位:8-20,产生 TraceId 的时间
- 再4位:自增的序列,从 1000 -> 9000,到9000后再回到 1000
- 最后5位:当前的进程 ID,防止单机多进程出现 TraceId 冲突的情况
-
Thread.currentThread().getId();
二、最佳实践
前端交互
前端与后端交互,诉求只想知道这次调用对应后端哪次调用链,方便排查问题。 所以只需要告诉前端,这次请求的 traceId 是多少。
- traceId:一般会在返回体的 Header 和 Body 中体现。
举个 🌰 栗子,在 HTTP 的 Response 的 Header中体现:X-Tracking-Id
举个 🌰 栗子,在 HTTP 的 Response 的 Body 中体现:traceId
json
代码解读
复制代码
{ "code": 0, "success": true, "message": null, "traceId": "933ce7302b0b4396a89b1a81747b0e46", "data": {} }
服务间交互
(1)服务间交互:Feign、Dubbo
Feign 请求拦截器中塞入 traceId:
java
代码解读
复制代码
@Slf4j public class FeignRequestInterceptor extends BasicAuthRequestInterceptor { @Override public void apply(RequestTemplate template) { template.header("X-Tracking-ID", MDC.get("traceId")); } }
Dubbo 消费者获取 traceId:
java
代码解读
复制代码
@Slf4j @Activate(group = {Constants.CONSUMER}, order = -99999) public class TrackIdConsumerFilter implements Filter { @Override public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException { String tid = MDC.get("traceId"); if (StringUtils.isBlank(tid)) { tid = UUIDUtils.UUID32(); } RpcContext.getContext().setAttachment("traceId", tid); return invoker.invoke(invocation); } @Override public Result onResponse(Result result, Invoker<?> invoker, Invocation invocation) { return Filter.super.onResponse(result, invoker, invocation); } }
Dubbo 生产者塞入 traceId:
java
代码解读
复制代码
@Slf4j @Activate(group = {Constants.PROVIDER}, order = -99999) public class TrackIdProviderFilter implements Filter { @Override public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException { String tid = invocation.getAttachment("traceId"); if (StringUtils.isBlank(tid)) { tid = UUIDUtils.UUID32(); } MDC.put("traceId", tid); try { return invoker.invoke(invocation); } finally { MDC.clear(); } } @Override public Result onResponse(Result result, Invoker<?> invoker, Invocation invocation) { return Filter.super.onResponse(result, invoker, invocation); } }
(2)MQ消息 / XXL-JOB 传递
这类可以封装对应注解,用 AOP 来统一处理下。
- 注解:
@TraceId
- AOP:
TraceIdAspect
java
代码解读
复制代码
@Target({ElementType.METHOD}) @Retention(RetentionPolicy.RUNTIME) public @interface XTraceId { }
java
代码解读
复制代码
@Aspect @Component @Slf4j public class TraceIdAspect { @Pointcut("@annotation(com.server.annotation.TraceId)") public void annotationPointCut() { } @Around("annotationPointCut()") public Object doAround(ProceedingJoinPoint pjp) throws Throwable { String traceId = UUIDUtils.nextId(""); MDC.put("traceId", traceId); try { return pjp.proceed(); } finally { MDC.remove("traceId"); } } }
举个 🌰 栗子,在 RocketMQ 中消息者消费消息时:
- 消费者执行消息时,用
traceId
把单次调用链串联起来。
java
代码解读
复制代码
@Slf4j @Component @RequiredArgsConstructor public class ConsumerListener implements MessageListener { @TraceId @Override public Action consume(Message message, ConsumeContext context) { try { // 业务处理 return Action.CommitMessage; } catch (Exception e) { // 异常处理 return Action.ReconsumeLater; } } }
举个 🌰 栗子,XXL-JOB 中使用:
java
代码解读
复制代码
@Slf4j @Component @JobHandler @RequiredArgsConstructor public class PushXXRobotContactJob extends IJobHandler { // 加上注解 @TraceId @Override public ReturnT<String> execute(String param) { return ReturnT.SUCCESS; } }
(3)多线程(父子线程)
由于 MDC 是基于 ThreadLocal 实现,上下文信息是线程私有的,并且 ThreadLocal 变量具有不继承性,所以如果代码中使用了多线程,traceId 是无法自动传递的。
官方建议: https://logback.qos.ch/manual/mdc.html
- 在父线程新建子线程之前调用
MDC.getCopyOfContextMap()
方法将 MDC 内容取出来传给子线程 - 子线程在执行操作前先调用
MDC.setContextMap()
方法将父线程的 MDC 内容设置到子线程
方式一:使用 Decorator
java
代码解读
复制代码
public class TraceIdTaskDecorator implements TaskDecorator { @Override public Runnable decorate(Runnable runnable) { Map<String, String> context = MDC.getCopyOfContextMap(); return () -> { try { MDC.setContextMap(context); runnable.run(); } finally { MDC.clear(); } }; } }
🌰 栗子1: @Async
java
代码解读
复制代码
@Slf4j @Configuration @EnableAsync public class AsyncConfig implements AsyncConfigurer { @Override public Executor getAsyncExecutor() { ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor(); executor.setCorePoolSize(3); executor.setMaxPoolSize(10); executor.setQueueCapacity(100); executor.setThreadNamePrefix("AsyncThread-"); executor.setTaskDecorator(MdcTaskDecorator::new); executor.initialize(); return executor; } private static class MdcTaskDecorator implements Runnable { private final Runnable delegate; public MdcTaskDecorator(Runnable delegate) { this.delegate = delegate; } @Override public void run() { String traceId = MDC.get("traceId"); if (StringUtils.isNotBlank(traceId)) { MDC.put("traceId", traceId); } try { delegate.run(); } finally { MDC.clear(); } } } }
方式二:使用 InheritableThreadLocal 对象
java
代码解读
复制代码
public class UserInheritableUtils { private static final InheritableThreadLocal<String> THREAD_LOCAL = new InheritableThreadLocal<>(); public static String get(){ return THREAD_LOCAL.get(); } public static void set(String val){ THREAD_LOCAL.set(val); } public static void clear(){ THREAD_LOCAL.remove(); } }
ThreadLocal 变量的不继承性
在使用 ThreadLocal 存储本地变量时,主线程与子线程之间不具有继承性。
在主线程中使用 ThreadLocal 对象保存本地变量后,无法通过同一个 ThreadLocal 对象获取到主线程中保存的只。
🌰 栗子1:子线程获取主线程的值
java
代码解读
复制代码
public class ThreadLocalTest { private static final ThreadLocal<String> THREAD_LOCAL = new ThreadLocal<>(); public static void main(String[] args) { THREAD_LOCAL.set("main_thread_donald"); // 主线程保存值 new Thread(() -> { // 子线程获取对应的值 System.out.println("在子线程中获取到的本地变量的值为:" + THREAD_LOCAL.get()); }).start(); System.out.println("在主线程中获取到的本地变量的值为:" + THREAD_LOCAL.get()); } }
输出结果如下:
结论:在主线程中通过 ThreadLocal 对象保存值后,在子线程中通过相同的 ThreadLocal 对象是无法获取到这个值的。
java
代码解读
复制代码
在主线程中获取到的本地变量的值为:main_thread_donald 在子线程中获取到的本地变量的值为:null Process finished with exit code 0
🌰 栗子2:InheritableThreadLocal 使用
如果需要在子线程中获取到主线程中保存的值,则可以使用 InheritableThreadLocal 对象。
java
代码解读
复制代码
public class InheritableThreadLocalTest { private static final ThreadLocal<String> THREAD_LOCAL = new InheritableThreadLocal<>(); public static void main(String[] args) { THREAD_LOCAL.set("main_thread_donald"); // 主线程保存值 new Thread(() -> { // 子线程获取对应的值 System.out.println("在子线程中获取到的本地变量的值为:" + THREAD_LOCAL.get()); }).start(); System.out.println("在主线程中获取到的本地变量的值为:" + THREAD_LOCAL.get()); } }
输出结果如下:
结论:在主线程中通过 InheritableThreadLocal 对象保存值后,在子线程中通过相同的 InheritableThreadLocal 对象是可以获取到这个值的。
shell
代码解读
复制代码
在主线程中获取到的本地变量的值为:main_thread_donald 在子线程中获取到的本地变量的值为:main_thread_donald Process finished with exit code 0
(4)sls 接入日志/查看
日常工作中,查询日志依赖阿里云的 sls。排查问题,会跟根据告警信息中的 traceId 进行查询。
- 接收告警信息:文本中带有 traceId
- 根据 traceId 查询调用链