マルチスレッド非同期環境における Trace 伝搬のベストプラクティス¶
Java スレッドの非同期処理でよく使われる実装方法は以下の通りです。
new ThreadExecutorService
他にも fork-join などがありますが、これらについては後述します。以下では、主に上記 2 つのシナリオについて、DDTrace と Spring Boot を組み合わせた実践方法を紹介します。
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
ログにトレース情報が出力されています。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 を作成します。
そして、現在の 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() メソッドを使用する際、ThreadLocal 内部では 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.
使いやすくするために、Span 情報を格納するユーティリティクラス InheritableThreadLocalUtil.java を作成します。
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
スレッド内の 2 つのログの 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 など、多くのスレッドコンポーネントフレームワークに対してトレース伝搬をサポートしています。
