Trace delivers best practices in a multi-threaded asynchronous system

Common implementation methods of JAVA thread asynchronous are:

new Thread
ExecutorService

Of course, there are others, such as fork-join, which will be mentioned below. The following mainly focuses on these two scenarios for practice with DDTrace and Springboot.

Introducing 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>
    ...

About the usage of DDTrace sdk reference document ddtrace-api usage guide

Logback configuration

Configure logback to output traceId and spanId, and apply the following pattern to all appender in.

<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" />

If link information is generated, Trace information will be output in the log.

new Thread

Implement a simple interface, use logback to output log information, and observe the log output.

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

After the request, the log is as follows

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 Time consuming: 39

There is trace information generated in the log. 7209831467195902001 is traceId, and 2587871298938674772 is spanId.

Add new Thread to this interface to create a thread.

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

Observe the log output by requesting the corresponding 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 fun c 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.

Through the log output, we found that the new Thread method cannot output Trace information, which means that Trace is not passed in.

Is it okay if we explicitly pass the Trace information in? Just do it.

Why doesn’t ThreadLocal work?

ThreadLocal Local thread variable, this variable is unique to the current thread.

For ease of use, we create a tool class ThreadLocalUtil.

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

The current Span information is then stored in 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";
    }

Observe the log output by requesting the corresponding 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 tracei D: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

Get the external thread ThreadLocal in the new thread, and the value obtained is null.

By analyzing the ThreadLocal source code, we found that when we use the set() method of ThreadLocal, ThreadLocal internally uses Thread.currentThread() serves as the key for data storage of ThreadLocal, that is to say, when obtaining variable information from a new thread, key has changed, so the value cannot be obtained.

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 extends ThreadLocal to provide inheritance of values from parent threads to child threads: when a child thread is created, the child thread receives all inheritable thread locals that the parent thread has values for The initial value of the variable.

Official explanation:

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.

For ease of use, we create a tool class InheritableThreadLocalUtil.java to store Span information

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

Replace ThreadLocalUtil with 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";
    }

Observe the log output by requesting the corresponding 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 tracei D: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

By observing the above log information, the span object address has been obtained inside the thread, but there is no Trace information output in the pattern part of the log. The reason is that DDTrace performs instrumentation processing on logback‘s getMDCPropertyMap() and getMdc() methods, and transfers the Trace information put into 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 & amp; & amp; !AgentTracer.traceConfig().isLogsInjectionEnabled()) {<!-- -->
        return;
      }

      Map<String, String> correlationValues = new HashMap<>(8);

      if (context != null) {<!-- -->
        DDTraceId traceId = context.getTraceId();
        String traceIdValue =
            InstrumenterConfig.get().isLogs128bTraceIdEnabled() & amp; & amp; 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 & amp; & amp; !serviceName.isEmpty()) {<!-- -->
        correlationValues.put(Tags.DD_SERVICE, serviceName);
      }
      String env = Config.get().getEnv();
      if (null != env & amp; & amp; !env.isEmpty()) {<!-- -->
        correlationValues.put(Tags.DD_ENV, env);
      }
      String version = Config.get().getVersion();
      if (null != version & amp; & amp; !version.isEmpty()) {<!-- -->
        correlationValues.put(Tags.DD_VERSION, version);
      }

      mdc = null != mdc ? new UnionMap<>(mdc, correlationValues) : correlationValues;
    }

In order for the log of the newly created thread to also obtain the trace information of the parent thread, this can be achieved by creating a span. The span needs to be a child span< of the parent thread. /code> to complete the concatenation.


 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();

Observe the log output by requesting the corresponding 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 tracei D: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:2303 424716416355903

Why does the pattern with two logs in the thread not output Trace information? The reason is that the span inside the current thread is created after the log is output. You only need to put the log below the span creation.
 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();

Observe the log output by requesting the corresponding 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 fun c 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:data dog.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:47282 8375731745486


ExecutorService
Create an API and create ExecutorService objects through Executors.
 @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";
    }

Observe the log output by requesting the corresponding 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 437036622195882390 8-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 The thread pool method will automatically transmit Trace information. This automatic capability comes from DDTrace's implementation of burying operations on corresponding components.
JAVA supports link transfer for many thread component frameworks, such as: ForkJoinTask, ForkJoinPool, TimerTask, FutureTask code>, ThreadPoolExecutor, etc.

Source code
springboot-ddtrace-server