java

关注公众号 jb51net

关闭
首页 > 软件编程 > java > Java应用日志与Jaeger的trace关联

关于Java应用日志与Jaeger的trace关联的问题

作者：itips

这篇文章主要介绍了Java应用日志如何与Jaeger的trace关联,通过jaeger发现这十次请求中有一次耗时特别长，想定位一下具体原因，感兴趣的朋友跟随小编一起看看吧

欢迎访问我的GitHub

https://github.com/zq2599/blog_demos

内容：所有原创文章分类汇总及配套源码，涉及Java、Docker、Kubernetes、DevOPS等；

本篇概览

一次web请求可能有多条业务日志(log4j或者logback配置的那种)，这和您写代码执行log.info的次数有关，假设有10条，那么十次请求就有一百条业务日志；

通过jaeger发现这十次请求中有一次耗时特别长，想定位一下具体原因，现在问题来了：一共有100条业务日志，到底哪些是和Jaeger中耗时长的那一次请求有关？

关于MDC

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <!--%logger{10}表示类名过长时会自动缩写-->
            <pattern>%d{HH:mm:ss} [%thread] %-5level %logger{10} [user-id=%X{user-id}] %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>

再来看一段日志的代码，先调用MDC.put方法将一个键值对写入当前线程的诊断上下文map(diagnostic context map)，键名和上面的模板中配置的%X{user-id}一模一样：

@GetMapping("/test")
    public void test() {
        MDC.put("user-id", "user-" + System.currentTimeMillis());
        log.info("this is test request");
    }

现在把代码运行起来，打印日志看看，如下所示，之前模板中配置的%X{user-id}已被替换成了user-1632122267618，就是代码中MDC.put设置的值：

15:17:47 [http-nio-18081-exec-6] INFO  c.b.j.c.c.HelloConsumerController [user-id=user-1632122267618] this is test request

以上就是MDC的基本功能：对日志模板中的变量进行填充，填充的内容可以用MDC.put方法随意设置；

此刻聪明的您应该能猜到jaeger官方的方案是如何实现的了，没错，就是借助MDC将trace信息填充到日志模板中，这样每行日志都有了trace信息，咱们在jaeger web页面中感兴趣的任何一次trace，都能找到对应的日志了

关于Jaeger的官方方案

Jaeger的官方方案如下图所示，SDK已经把traceId、spanId、sampled写入当前线程的诊断上下文map(diagnostic context map)，只要日志模板中配置上述三个变量，就会在所有业务日志中输出它们具体的值：

看起来似乎非常简单，那就动手编码试试吧

编码实战

<?xml version="1.0" encoding="UTF-8"?>

<configuration scan="true" scanPeriod="60 seconds" debug="false">

    <contextName>logback</contextName>

    <!--输出到控制台-->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <!--%logger{10}表示类名过长时会自动缩写-->
            <pattern>%d{HH:mm:ss} [%thread] %-5level %logger{10} [traceId=%X{traceId} spanId=%X{spanId} sampled=%X{sampled}] %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>

    <root level="info">
        <appender-ref ref="console" />
    </root>
</configuration>

再去检查配置类，确认JaegerTracer实例化时用了MDCScopeManager参数，如下所示，咱们在上一章已经这么做了，可以维持不变：

package com.bolingcavalry.jaeger.provider.config;

import io.jaegertracing.internal.MDCScopeManager;
import io.opentracing.contrib.java.spring.jaeger.starter.TracerBuilderCustomizer;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class JaegerConfig {
    @Bean
    public TracerBuilderCustomizer mdcBuilderCustomizer() {
        // 1.8新特性，函数式接口
        return builder -> builder.withScopeManager(new MDCScopeManager.Builder().build());
    }
}

接下来是在业务代码中随意加几行打印日志的代码，如下图红框所示：

接下来继续修改jaeger-service-consumer子工程，具体步骤与刚才改造jaeger-service-provider时一模一样，就不多占用篇幅赘述了，记得在业务代码中随意加几行日志，如下图红框：

开发完成，开始验证吧

验证

此时会跳转到该trace的详情页，注意页面的url，如下图红框，里面的2037fe105d73f4a5就是traceid：

用2037fe105d73f4a5搜索jaeger-service-provider的日志，由于应用部署在docker中，咱们要用docker log和grep命令组合来过滤，如下所示，咱们代码写的日志都打印出来了，并且红框中就是traceid等关键信息

再去查看jaeger-service-consumer的日志，如下图红框，本次请求相关的日志也可以通过traceid搜索到：

至此，本篇实战就完成了，Jaeger的web页面上的任何一个trace，现在都能轻易找到与之对应的所有业务日志，这在定位问题时简直是如虎添翼的效果，如果您的系统用了ELK或者EFK来汇总所有分布式服务的日志，那就更高效了

到此这篇关于Java应用日志如何与Jaeger的trace关联的文章就介绍到这了,更多相关Java应用日志与Jaeger的trace关联内容请搜索脚本之家以前的文章或继续浏览下面的相关文章希望大家以后多多支持脚本之家！

您可能感兴趣的文章:
阅读全文