Trace?在多線程異步體系下傳遞流程解析

更新時間：2023年12月20日 11:38:54 作者：觀測云

這篇文章主要為大家介紹了Trace?在多線程異步體系下傳遞流程解析,有需要的朋友可以借鑒參考下,希望能夠有所幫助,祝大家多多進(jìn)步,早日升職加薪

JAVA 線程異步常見的實現(xiàn)方式有

new Thread
ExecutorService

當(dāng)然還有其他的，比如fork-join，這些下文會有提及，下面主要針對這兩種場景結(jié)合 DDTrace 和 Springboot 下進(jìn)行實踐。

引入 DDTrace sdk

<properties>
        <java.version>1.8</java.version>
        <dd.version>1.21.0</dd.version>
    </properties>
    <dependencies>
        <dependency>
            <groupId>com.datadoghq</groupId>
            <artifactId>dd-trace-api</artifactId>
            <version>${dd.version}</version>
        </dependency>

        <dependency>
            <groupId>io.opentracing</groupId>
            <artifactId>opentracing-api</artifactId>
            <version>0.33.0</version>
        </dependency>
        <dependency>
            <groupId>io.opentracing</groupId>
            <artifactId>opentracing-mock</artifactId>
            <version>0.33.0</version>
        </dependency>
        <dependency>
            <groupId>io.opentracing</groupId>
            <artifactId>opentracing-util</artifactId>
            <version>0.33.0</version>
        </dependency>
    ...

關(guān)于 DDTrace sdk 使用方式參考文檔ddtrace-api使用指南

Logback 配置

配置 logback ，讓其輸出 traceId 和 spanId，將以下 pattern 應(yīng)用到所有的 appender 中。

<property name="log.pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - [%method,%line] %X{dd.service} %X{dd.trace_id} %X{dd.span_id} - %msg%n" />

如果有鏈路信息產(chǎn)生，則會在日志里面輸出 Trace 信息。

new Thread

實現(xiàn)一個簡單的接口，使用 logback 輸出日志信息，觀察日志輸出情況

@RequestMapping("/thread")
    @ResponseBody
    public String threadTest(){
        logger.info("this func is threadTest.");
        return "success";
    }

請求后，日志如下

2023-10-23 11:33:09.983 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.CalcFilter - [doFilter,28] springboot-server 7209831467195902001 958235974016818257 - START /thread
host localhost:8086
connection Keep-Alive
user-agent Apache-HttpClient/4.5.14 (Java/17.0.7)
accept-encoding br,deflate,gzip,x-gzip
2023-10-23 11:33:10.009 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,277] springboot-server 7209831467195902001 2587871298938674772 - this func is threadTest.
2023-10-23 11:33:10.022 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.CalcFilter - [doFilter,34] springboot-server 7209831467195902001 958235974016818257 - END : /thread耗時：39

日志里面有 trace 信息產(chǎn)生， 7209831467195902001為 traceId，2587871298938674772為 spanId。

向該接口加入 new Thread ，創(chuàng)建一個線程。

@RequestMapping("/thread")
    @ResponseBody
    public String threadTest(){
        logger.info("this func is threadTest.");
        new Thread(()->{
            logger.info("this is new Thread.");
        }).start();
        return "success";
    }

通過請求對應(yīng)的 URL，觀察日志輸出情況。

2023-10-23 11:40:00.994 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,277] springboot-server 319673369251953601 5380270359912403278 - this func is threadTest.
2023-10-23 11:40:00.995 [Thread-10] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,279] springboot-server - this is new Thread.

通過日志輸出發(fā)現(xiàn)，new Thread 方式，并不能夠輸出 Trace 信息，也就是說 Trace 并未傳遞進(jìn)去。

如果我們顯示的把 Trace 信息傳遞進(jìn)去是不是就可以了，說干就干。

ThreadLocal 為什么不行

ThreadLocal 本地線程變量，該變量為當(dāng)前線程獨(dú)有。

為了方便使用，我們創(chuàng)建一個工具類 ThreadLocalUtil。

public static final ThreadLocal<Span> THREAD_LOCAL = new ThreadLocal<>();

然后將當(dāng)前 Span 信息存儲到 ThreadLocal。

@RequestMapping("/thread")
    @ResponseBody
    public String threadTest(){
        logger.info("this func is threadTest.");
        ThreadLocalUtil.setValue(GlobalTracer.get().activeSpan());
        logger.info("current traceiD:{}",GlobalTracer.get().activeSpan().context().toTraceId());

        new Thread(()->{
            logger.info("this is new Thread.");
            logger.info("new Thread get span:{}",ThreadLocalUtil.getValue());
        }).start();
        return "success";
    }

通過請求對應(yīng)的 URL，觀察日志輸出情況。

2023-10-23 14:14:02.339 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 4492960774800816442 4097884453719637622 - this func is threadTest.
2023-10-23 14:14:02.340 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 4492960774800816442 4097884453719637622 - current traceiD:4492960774800816442
2023-10-23 14:14:02.341 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,283] springboot-server - this is new Thread.
2023-10-23 14:14:02.342 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,284] springboot-server - new Thread get span:null

在新線程內(nèi)獲取外部線程 ThreadLocal，獲取到的值為 null。

通過分析ThreadLocal源碼發(fā)現(xiàn)，當(dāng)我們使用 ThreadLocal 的 set() 方法時，ThreadLocal 內(nèi)部使用了Thread.currentThread()作為了 ThreadLocal 的數(shù)據(jù)存儲的 key，也就是說當(dāng)從新線程里面獲取變量信息，key 發(fā)生了變化，所以取不到值。

public class ThreadLocal<T> {
    ...
   public void set(T value) {
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null) {
            map.set(this, value);
        } else {
            createMap(t, value);
        }
    }
    public T get() {
        Thread t = Thread.currentThread();
        ThreadLocalMap map = getMap(t);
        if (map != null) {
            ThreadLocalMap.Entry e = map.getEntry(this);
            if (e != null) {
                @SuppressWarnings("unchecked")
                T result = (T)e.value;
                return result;
            }
        }
        return setInitialValue();
    }
    ...
}

InheritableThreadLocal

InheritableThreadLocal 擴(kuò)展了 ThreadLocal，以提供從父線程到子線程的值繼承：當(dāng)創(chuàng)建子線程時，子線程接收父線程具有值的所有可繼承線程局部變量的初始值。

官方解釋：

This class extends ThreadLocal to provide inheritance of values from parent thread to child thread: when a child thread is created, the child receives initial values for all inheritable thread-local variables for which the parent has values. Normally the child's values will be identical to the parent's; however, the child's value can be made an arbitrary function of the parent's by overriding the childValue method in this class.
Inheritable thread-local variables are used in preference to ordinary thread-local variables when the per-thread-attribute being maintained in the variable (e.g., User ID, Transaction ID) must be automatically transmitted to any child threads that are created.
Note: During the creation of a new thread, it is possible to opt out of receiving initial values for inheritable thread-local variables.

為了方便使用，我們創(chuàng)建一個工具類 InheritableThreadLocalUtil.java，用于存放 Span 信息

public static final InheritableThreadLocal<Span> THREAD_LOCAL = new InheritableThreadLocal<>();

將 ThreadLocalUtil 換成 InheritableThreadLocalUtil

@RequestMapping("/thread")
    @ResponseBody
    public String threadTest(){
        logger.info("this func is threadTest.");
        InheritableThreadLocalUtil.setValue(GlobalTracer.get().activeSpan());
        logger.info("current traceiD:{}",GlobalTracer.get().activeSpan().context().toTraceId());

        new Thread(()->{
            logger.info("this is new Thread.");
            logger.info("new Thread get span:{}",InheritableThreadLocalUtil.getValue());
        }).start();
        return "success";
    }

通過請求對應(yīng)的 URL，觀察日志輸出情況。

2023-10-23 14:37:05.415 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 8754268856419787293 5276611939997441402 - this func is threadTest.
2023-10-23 14:37:05.416 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 8754268856419787293 5276611939997441402 - current traceiD:8754268856419787293
2023-10-23 14:37:05.416 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,283] springboot-server - this is new Thread.
2023-10-23 14:37:05.417 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,284] springboot-server - new Thread get span:datadog.trace.instrumentation.opentracing32.OTSpan@712ad7e2

通過觀測以上日志信息，線程內(nèi)部已經(jīng)獲取到了 span 對象地址，但日志 pattern 部分并沒有 Trace 信息輸出，原因在于，DDTrace 對 logback 的getMDCPropertyMap()和 getMdc()方法做了插樁處理,將 Trace 信息 put 到 MDC 中。

@Advice.OnMethodExit(suppress = Throwable.class)
    public static void onExit(
        @Advice.This ILoggingEvent event,
        @Advice.Return(typing = Assigner.Typing.DYNAMIC, readOnly = false)
            Map<String, String> mdc) {
      if (mdc instanceof UnionMap) {
        return;
      }
      AgentSpan.Context context =
          InstrumentationContext.get(ILoggingEvent.class, AgentSpan.Context.class).get(event);
      // Nothing to add so return early
      if (context == null && !AgentTracer.traceConfig().isLogsInjectionEnabled()) {
        return;
      }
      Map<String, String> correlationValues = new HashMap<>(8);
      if (context != null) {
        DDTraceId traceId = context.getTraceId();
        String traceIdValue =
            InstrumenterConfig.get().isLogs128bTraceIdEnabled() && traceId.toHighOrderLong() != 0
                ? traceId.toHexString()
                : traceId.toString();
        correlationValues.put(CorrelationIdentifier.getTraceIdKey(), traceIdValue);
        correlationValues.put(
            CorrelationIdentifier.getSpanIdKey(), DDSpanId.toString(context.getSpanId()));
      }else{
        AgentSpan span = activeSpan();
        if (span!=null){
          correlationValues.put(
              CorrelationIdentifier.getTraceIdKey(), span.getTraceId().toString());
          correlationValues.put(
              CorrelationIdentifier.getSpanIdKey(), DDSpanId.toString(span.getSpanId()));
        }
      }
      String serviceName = Config.get().getServiceName();
      if (null != serviceName && !serviceName.isEmpty()) {
        correlationValues.put(Tags.DD_SERVICE, serviceName);
      }
      String env = Config.get().getEnv();
      if (null != env && !env.isEmpty()) {
        correlationValues.put(Tags.DD_ENV, env);
      }
      String version = Config.get().getVersion();
      if (null != version && !version.isEmpty()) {
        correlationValues.put(Tags.DD_VERSION, version);
      }
      mdc = null != mdc ? new UnionMap<>(mdc, correlationValues) : correlationValues;
    }

為了讓新創(chuàng)建的線程的日志也能夠獲取父線程 Trace 信息，可以通過創(chuàng)建 span 來實現(xiàn)，該 span 需要作為父線程的子 span才能完成串聯(lián)。

new Thread(()->{
        logger.info("this is new Thread.");
        logger.info("new Thread get span:{}",InheritableThreadLocalUtil.getValue());
        Span span = null;
        try {
            Tracer tracer = GlobalTracer.get();
            span = tracer.buildSpan("thread")
                    .asChildOf(InheritableThreadLocalUtil.getValue())
                    .start();
            span.setTag("threadName", Thread.currentThread().getName());
            GlobalTracer.get().activateSpan(span);
            logger.info("thread:{}",span.context().toTraceId());
        }finally {
            if (span!=null) {
                span.finish();
            }
        }
    }).start();

通過請求對應(yīng)的 URL，觀察日志輸出情況。

2023-10-23 14:51:28.969 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 2303424716416355903 7690232490489894572 - this func is threadTest.
2023-10-23 14:51:28.969 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 2303424716416355903 7690232490489894572 - current traceiD:2303424716416355903
2023-10-23 14:51:28.970 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,283] springboot-server - this is new Thread.
2023-10-23 14:51:28.971 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,284] springboot-server - new Thread get span:datadog.trace.instrumentation.opentracing32.OTSpan@c3a1aae
2023-10-23 14:51:28.971 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,292] springboot-server - thread:2303424716416355903
2023-10-23 14:51:28.971 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,294] springboot-server 2303424716416355903 5766505477412800739 - thread:2303424716416355903

為何線程內(nèi)有兩條日志的 pattern 沒有輸出 Trace 信息？原因在于當(dāng)前線程內(nèi)部的 span 是在日志輸出之后創(chuàng)建的，只需要將日志放到 span 創(chuàng)建下面即可。

new Thread(()->{
        Span span = null;
        try {
            Tracer tracer = GlobalTracer.get();
            span = tracer.buildSpan("thread")
                    .asChildOf(InheritableThreadLocalUtil.getValue())
                    .start();
            span.setTag("threadName", Thread.currentThread().getName());
            GlobalTracer.get().activateSpan(span);
            logger.info("this is new Thread.");
            logger.info("new Thread get span:{}",InheritableThreadLocalUtil.getValue());
            logger.info("thread:{}",span.context().toTraceId());
        }finally {
            if (span!=null) {
                span.finish();
            }
        }
    }).start();

通過請求對應(yīng)的 URL，觀察日志輸出情況。

2023-10-23 15:01:00.490 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 472828375731745486 6076606716618097397 - this func is threadTest.
2023-10-23 15:01:00.491 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 472828375731745486 6076606716618097397 - current traceId:472828375731745486
2023-10-23 15:01:00.492 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,291] springboot-server 472828375731745486 9214366589561638347 - this is new Thread.
2023-10-23 15:01:00.492 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,292] springboot-server 472828375731745486 9214366589561638347 - new Thread get span:datadog.trace.instrumentation.opentracing32.OTSpan@12fd40f0
2023-10-23 15:01:00.493 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,293] springboot-server 472828375731745486 9214366589561638347 - thread:472828375731745486

ExecutorService

創(chuàng)建一個 API ，并通過Executors 創(chuàng)建 ExecutorService對象。

@RequestMapping("/execThread")
    @ResponseBody
    public String ExecutorServiceTest(){
        ExecutorService executor = Executors.newCachedThreadPool();
        logger.info("this func is ExecutorServiceTest.");
        executor.submit(()->{
            logger.info("this is executor Thread.");
        });
        return "ExecutorService";
    }

通過請求對應(yīng)的 URL，觀察日志輸出情況。

2023-10-23 15:24:41.828 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [ExecutorServiceTest,309] springboot-server 2170215511602500482 4370366221958823908 - this func is ExecutorServiceTest.
2023-10-23 15:24:41.832 [pool-2-thread-1] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$ExecutorServiceTest$2,311] springboot-server 2170215511602500482 4370366221958823908 - this is executor Thread.

ExecutorService 線程池方式會自動傳遞 Trace 信息，這種自動的能力源于 DDTrace 對相應(yīng)組件埋點(diǎn)操作實現(xiàn)。

JAVA 對于很多線程組件框架都做了鏈路傳遞的支持，如：ForkJoinTask、ForkJoinPool、TimerTask、FutureTask、ThreadPoolExecutor等等。