「雕虫小技」基于日志的链路追踪实现方案

发表于

⚠️本文为掘金社区首发签约文章，未获授权禁止转载

什么是链路追踪

就像一份外卖订单，从用户点单 - 商家接单 - 商家制作 - 外卖员取餐 - 送餐一样，每一个业务都有其特定的执行流程，把它细分到代码、应用层级，就可以称为执行链路，当前请求/业务到底是如何一步一步执行到结束的，它在哪一个阶段发生异常被迫终止的，这都是程序员想要知道的，因为这些讯息可以帮助我们定位并解决问题。

这种业务执行链路在数据层面肯定会有所体现，但是它可能还不够具体和详细，因此大部分链路追踪的实现方式是基于日志来体现的，从程序的入口到最后一层出口，让它中间的每一行日志都有其特定的唯一标识，将之串联起来，就成了一条完整的链路。

链路追踪的使用场景

我们可以基于链路追踪的能力从不同维度做各种事情，这就要考虑各位读者的需要和想象力了😜

image-20210818082741431.png

应用链路

应用链路指的是单体应用内的链路追踪，它最大的用处便是提高大量日志下问题定位的效率。

比如在电商业务系统中，商品处理细节非常繁琐，由于业务的特殊性，某一个商品变更MQ会同时触发多个类似业务线的处理，这几条业务线同时收到消息，共同处理，在毫秒间的差距里可能打出上千条日志，除非事先就有规划的设计日志打印的规则，否则想在上千条日志里找到某一条线路的完整执行状态，简直就是匪夷所思，此时，应用链路日志就派上了用处，我只需要从入口处分析出TraceId，然后二次搜索即可。

亦或是和用户直接打交道的网关系统，需要分析出用户当前登录状态下的所有行为，我们只需要把SessionId或者UserId打印在日志内，然后通过搜索即可得到全部的信息，拿到这些信息我们甚至可以反推算出用户行为进行深度分析，或者存入流量系统用作压测流量回放等等。

image-20210818084229606.png

比如基于上图中的日志就可以看出，该用户使用APP版本为8.1.5，先进行了登录动作，再查看个人信息，翻阅了APP首页，继而进入爆款专区，查看了两个商品，然后执行了加入购物车操作，整个用户动作基于用户SessionId进行筛选，时间进行排序，非常的清晰。

全链路

全链路指的是在微服务架构下，用户某次请求从APP/H5到网关、中台、底层服务的全部链路。

全链路追踪的价值不仅仅在于协助问题定位那么简单，它还能做这些事：

  • 基于全链路日志分析，梳理出整个公司架构体系下的调用链路

中小公司的应用可能不多，但稍大的公司的架构体系可能是上百个系统互相交织在一起，无比复杂

  • 已知调用链路后，还可以分析出整个请求的耗时阶段，进行性能优化等等
  • 统计应用的流量占比，即分析出当前系统对外提供的流量都消耗在哪些系统上
  • ….

总之，数据为王，只要能够获取全链路的链路追踪数据就可以不断挖掘出内在的价值，优化整个架构体系。

系统级链路追踪的实现方案

上文讲述了什么是链路追踪，以及它蕴含的巨大业务价值，但相反的是，它的实现可能无比简单，以一个网关系统实现单应用内链路追踪为例。

AOP + ThreadLocal

AOP：面向切面编程，通过预编译方式和运行期动态代理实现程序功能的统一维护的一种技术。

ThreadLocal：ThreadLocal提供了线程内存储变量的能力，这些变量不同之处在于每一个线程读取的变量是对应的互相独立的。

我们刚提到了本例是基于一个网关系统而言，因此使用拦截器即可完美实现AOP的效果，核心代码如下：

1
2
3
4
5
6
7
8
9
10
java复制代码@Service
public class LogService {
    private static final Logger logger = LoggerFactory.getLogger(LogService.class);
    public Map<String, String> handle() {
        Map<String, String> map = new HashMap<>();
        map.put("Name", "Kerwin");
        logger.info("LogService.handle, TraceId:{}", ThreadLocalDemo.getLocal());
        return map;
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
java复制代码@RestController
public class LogDemo {

    @Resource
    LogService logService;

    @RequestMapping("/test")
    @ResponseBody
    public Map<String, String> test() {
        return logService.handle();
    }
}

此时通过PostMan/浏览器发起请求，得到的日志效果为：

1
bash复制代码2021-08-16 01:32:39  INFO 13956 --- [nio-8080-exec-7] com.boot.service.LogService              27 : LogService.handle, TraceId:null

实现拦截器，具体代码为：

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
30
java复制代码@Component
public class MvcConfigurer implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        ThreadLocalDemo.setLocal(UUID.randomUUID().toString());
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {

    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        ThreadLocalDemo.remove();
    }

    @Configuration
    class InterceptorConfig implements WebMvcConfigurer {
        
        // 拦截全部入口
        @Override
        public void addInterceptors(InterceptorRegistry registry) {
            InterceptorRegistration registration = registry.addInterceptor(new MvcConfigurer());
            registration.addPathPatterns("/**");
        }
    }
}

工具类核心代码为：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
java复制代码public class ThreadLocalDemo {

    private static ThreadLocal<String> local = new ThreadLocal<>();

    public static void setLocal(String demo) {
        local.set(demo);
    }

    public static String getLocal() {
        return local.get();
    }

    public static void remove() {
        local.remove();
    }
}

再次发起请求，观察日志为：

1
bash复制代码2021-08-16 01:40:26  INFO 16564 --- [nio-8080-exec-1] com.boot.service.LogService              27 : LogService.handle, TraceId:72df9e08-ffcf-465b-81cd-002f6d06b148

如文中所示，一个非常简单的网关系统链路追踪就完成了，如果换为其他底层系统，只需要在对外接口进行切面处理即可，效果是类似的。

但是上述方案存在几个问题，例如：

  1. 此方案需要在日志打印处额外打印TraceId，增加编码成本
  2. 硬编码方式导致拓展性极差

MDC 方案

其实在思考方案一的时候就能发现到，我们是把唯一标识（TraceId）存放在了系统内部然后用日志Logger打印出来，那么我们能不能直接拿到每一个Logger里面的上下文呢，要知道日志框架同样是服务于每一个线程的，于是一个新的概念就诞生了，即MDC。

MDC（Mapped Diagnostic Contexts）：映射调试上下文，主要用在做日志链路跟踪时，动态配置用户自定义的一些信息，比如RequestId、TraceId等等。

鉴于在工业级使用的时候我们都会依赖Slf4j，因此本例也是基于此来实现的，关于日志框架的细节，请见文章：动态日志级别：小功能，大用处。

还是刚才的那一段代码，先来看Controller层和Service层。

1
2
3
4
5
6
7
8
9
10
11
12
java复制代码@RestController
public class LogDemo {

    @Resource
    LogService logService;

    @RequestMapping("/test")
    @ResponseBody
    public Map<String, String> test() {
        return logService.handle();
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
java复制代码@Service
public class LogService {

    private static final Logger logger = LoggerFactory.getLogger(LogService.class);

    public Map<String, String> handle() {
        Map<String, String> map = new HashMap<>();
        map.put("Name", "Kerwin");
        logger.info("LogService.handle");
        return map;
    }
}

注意到几点变化：

  1. Controller层直接依赖Service层，没有任何变化
  2. Service层去掉了显示日志打印

拦截器代码由ThreadLocal调整为MDC，代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
java复制代码@Component
public class MvcConfigurer implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        MDC.put("TraceId", UUID.randomUUID().toString());
        return true;
    }

    // ....

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
    	MDC.clear();
    }
}

日志的输出格式增加相关内容，如下：

1
2
3
4
5
xml复制代码<!--原-->
<Property name="PATTERN_FORMAT">%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%t] %class{36} (%L) %M - %msg%xEx%n</Property>

<!--新-->
<Property name="PATTERN_FORMAT">[%X{TraceId}] %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%t] %class{36} (%L) %M - %msg%xEx%n</Property>

结果输出如下：

1
bash复制代码[1e6f506b-17ec-452f-a727-a42ebb03e154] 2021-08-16 02:01:58  INFO 17936 --- [nio-8080-exec-1] com.boot.service.LogService              26 : LogService.handle

看到这里的小伙伴可能会猜测所谓的MDC只不过是日志框架自己的ThreadLocal罢了。

我想说的是确实差不多，所有技术深入到原理层之后，其实也就那样，因为我们使用的是Slf4j的门面，它的核心类是：MDC，实际工作者是：MDCAdapter，根据所绑定的日志实现框架不同有所区别，比如以Logback为例，与之对应的实现是LogbackMDCAdapter，底层使用的数据结构是：

1
java复制代码final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();

与Logback不同的是Log4j2 MDC的实现类是：Log4jMDCAdapter，它的底层实现会相对复杂一些，使用了ThreadContext类屏蔽了较为复杂的设计，但本质上依然是ThreadLocal的变形罢了，值得注意的是，Log4j2的MDC方案支持父子线程的参数传递，配置方式是：

1
2
3
java复制代码static {
	System.setProperty("log4j2.isThreadContextMapInheritable", "true");
}

当开启了isThreadContextMapInheritable能力后，其底层实现会有稍许不同，如下所示：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
java复制代码// isThreadContextMapInheritable true 即入参为true
static ThreadLocal<Map<String, String>> createThreadLocalMap(final boolean isMapEnabled) {
    if (inheritableMap) {
        return new InheritableThreadLocal<Map<String, String>>() {
            @Override
            protected Map<String, String> childValue(final Map<String, String> parentValue) {
                return parentValue != null && isMapEnabled //
                    ? Collections.unmodifiableMap(new HashMap<>(parentValue)) //
                    : null;
            }
        };
    }
    // if not inheritable, return plain ThreadLocal with null as initial value
    return new ThreadLocal<>();
}

当开启了这项能力后，MDC将会创建InheritableThreadLocal进行临时变量的存储，那么它有什么能力呢？

InheritableThreadLocal使父线程生成的变量可以传递到子线程中进行使用。

我们来测试一下效果：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
java复制代码public class LogDemo {

    static {
        System.setProperty("log4j2.isThreadContextMapInheritable", "true");
    }

    private static Logger logger = LoggerFactory.getLogger(LogDemo.class);

    public static void main(String[] args) throws InterruptedException {
        MDC.put("threadId", "Kerwin~");

        logger.info("Just a Demo~");
        new Thread(() -> logger.info("Inheritable Test...")).start();
        Thread.sleep(1000);
    }
}

// 输出结果为：
[Kerwin~] 2021-08-16 03:39:38.764 INFO  [main] LogDemo (24) main - Just a Demo~
[Kerwin~] 2021-08-16 03:39:38.769 INFO  [Thread-1] LogDemo (25) lambda$main$0 - Inheritable Test...

全链路追踪的实现方案

在我们了解完系统级链路追踪方案之后，全链路追踪核心要解决的问题大家可能已经有了答案，即：链路的延续（TraceId的传递）。

首先明确一点：

  • 服务间如果想传递TraceId，一定需要进行数据传输

那么为了实现数据传输，同时避免硬编码，架构师们一定会在类似拦截器一样的位置进行设计和编码，避免影响业务代码。

如果我们仅仅是希望传递TraceId，那么在RPC层框架的调用入口处增加隐式参数：TraceId即可，然后底层进行接受继续透传到下一个系统，就完成了最简单的链路追踪。

如果想要实现更加强大的分析能力，我们就需要收集更多的信息，可能需要引入如：Zipkin或阿里的Tracing这样的分析工具，依然是在上文提到的位置进行拦截，把详细的数据传输给它们而已，本质没有任何变化。

以Zipkin为例，我们来梳理一下全链路的大致工作流程，：

1
2
bash复制代码网关请求入口创建TraceId --------> A服务的RPC接口 --------> B服务的RPC接口
                     TraceId上报              TraceId上报

各节点数据都上报至Zipkin之后，由它进行数据汇聚和专项分析，再提供统一的入口来查询日志，下图是它的内部工作原理：

图片来源：ZipKin官方网站

image-20210818085945978.png

有了类似的中间件工具，我们只需要在自己的框架接入即可，比如 SpringBoot 2.0 版本之后，Zipkin已经提供了专门的Starter，可以非常方便的接入并使用，大家有兴趣的可以自行尝试一下。

总结

本文介绍了基于日志方式的链路追踪原理及实现，它的设计其实并不复杂，关键在于如何更灵活的应用，下面是几点小建议：

  1. 尽量让系统具备链路追踪的能力，配置起来非常简单，关键时候可以起到很大的用处。
  2. 尽量使用日志框架的MDC能力，避免重复造轮子。
  3. 全链路日志尽量使用现有工具和平台，可以提供更强大的分析能力。

如果觉得这篇内容对你有帮助的话：

  1. 当然要点赞支持一下啦~
  2. 另外，可以搜索并关注公众号「是Kerwin啊」，一起在技术的路上走下去吧~ 😋

本文转载自: 掘金

开发者博客 – 和开发相关的 这里全都有

0%