Trace 다중 스레드 비동기 환경에서의 전파 모범 사례¶

JAVA 스레드 비동기 구현 방식은 일반적으로 다음과 같습니다:

new Thread
ExecutorService

물론 fork-join 등 다른 방식도 있으며, 이에 대해서는 아래에서 언급하겠습니다. 주로 위 두 가지 시나리오에 대해 DDTrace 및 Springboot와 결합하여 실제로 적용해 보겠습니다.

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

DDTrace SDK 사용 방법은 문서 ddtrace-api 사용 가이드를 참조하세요.

Logback 구성¶

logback을 구성하여 traceId와 spanId를 출력하도록 하고, 다음 pattern을 모든 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" />

링크 정보가 생성되면 로그에 Trace 정보가 출력됩니다.

new Thread¶

간단한 인터페이스를 구현하고 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 정보가 나타납니다. 7209831467195902001은 traceId이고, 2587871298938674772은 spanId입니다.

해당 인터페이스에 new Thread를 추가하여 스레드를 생성합니다.

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

해당 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.

로그 출력을 통해 new Thread 방식은 Trace 정보를 출력할 수 없음을 확인했습니다. 즉, Trace가 전달되지 않은 것입니다.

그렇다면 Trace 정보를 명시적으로 전달하면 되지 않을까? 바로 시도해 보겠습니다.

ThreadLocal이 작동하지 않는 이유¶

ThreadLocal은 로컬 스레드 변수로, 해당 변수는 현재 스레드에만 고유합니다.

편의를 위해 유틸리티 클래스 ThreadLocalUtil을 생성합니다.

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

그런 다음 현재 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";
    }

해당 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

새 스레드 내에서 외부 스레드의 ThreadLocal을 가져오면 null 값이 반환됩니다.

ThreadLocal 소스 코드를 분석해 보면, ThreadLocal의 set() 메서드를 사용할 때 내부적으로 Thread.currentThread()를 ThreadLocal 데이터 저장의 key로 사용합니다. 즉, 새 스레드에서 변수 정보를 가져오면 key가 변경되어 값을 가져올 수 없습니다.

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은 ThreadLocal을 확장하여 부모 스레드에서 자식 스레드로 값 상속을 제공합니다. 즉, 자식 스레드가 생성될 때 부모 스레드가 값을 가지고 있는 모든 상속 가능한 스레드 로컬 변수의 초기값을 자식 스레드가 받습니다.

공식 설명:

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.

편의를 위해 유틸리티 클래스 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";
    }

해당 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

위 로그 정보를 통해 스레드 내부에서 span 객체 주소를 가져온 것을 확인할 수 있지만, 로그 pattern 부분에는 Trace 정보가 출력되지 않습니다. 그 이유는 DDTrace가 logback의 getMDCPropertyMap() 및 getMdc() 메서드를 인스트루먼테이션하여 Trace 정보를 MDC에 put하기 때문입니다.

    @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;
    }

새로 생성된 스레드의 로그도 부모 스레드의 Trace 정보를 가져올 수 있도록 하려면 span을 생성하여 구현할 수 있습니다. 이 span은 부모 스레드의 하위 span이어야만 연결이 완료됩니다.

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

해당 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

스레드 내부에 두 개의 로그 pattern에 Trace 정보가 출력되지 않은 이유는 무엇일까요? 현재 스레드 내부의 span이 로그 출력 이후에 생성되었기 때문입니다. 로그를 span 생성 아래에 배치하기만 하면 됩니다.

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

해당 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¶

API를 생성하고 Executors를 통해 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";
    }

해당 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가 해당 구성 요소에 대한 인스트루먼테이션 작업을 구현했기 때문에 가능합니다.

JAVA는 많은 스레드 구성 요소 프레임워크에 대해 링크 전달을 지원합니다. 예: ForkJoinTask, ForkJoinPool, TimerTask, FutureTask, ThreadPoolExecutor 등.

소스 코드¶

springboot-ddtrace-server

Trace 다중 스레드 비동기 환경에서의 전파 모범 사례¶

DDTrace SDK 도입¶

Logback 구성¶

new Thread¶

ThreadLocal이 작동하지 않는 이유¶

InheritableThreadLocal¶

ExecutorService¶

소스 코드¶

이 페이지가 도움이 되었나요? ×

이 페이지가 도움이 되었나요?