はじめに
Opentlemetryの分散トレーシングについていろいろ調査したが基本的にWebアプリのトレーシングに関する内容がほとんどで、APIをコールするBatchアプリについてトレーシングしたい場合の方法がわからなかったので、BatchアプリにおけるOpentelemetryの検証を行った。
今回はその検証内容についてメモとしてまとめる。
実現したい分散トレーシングのイメージは下図のとおりで、Batchアプリの起動から終了までの間を1Traceとしてトレーシングするのが目標。
利用するバージョンは下記の通り。
- opentelemetry：1.0.1
- Zipkin：2.23.2
- Java：OpenJDK 11.0.2
検証1：Webアプリ側のトレーシング検証
WebアプリのWebApp01に対してAPI Callしたときに正しく動作するか確認を行った。
WebApp01およびWebApp02はSpringBootで実装しており、ログにはTraceIdとSpanIdを出力する設定を入れている。
Webアプリの起動時にこちらの記事に記載されている方式を参考にし、あらかじめダウンロードしたAgentのjarを起動オプション指定し実行する。
Webアプリの起動コマンドは下記の通りである。
$ java -javaagent:opentelemetry-javaagent-all.jar -Dotel.traces.exporter=zipkin \
-Dotel.zipkin.endpoint=http://localhost:9411/api/v2/spans \
-Dotel.exporter.zipkin.service.name=web_app_01 \
-Dotel.metrics.exporter=none \ # メトリックスはOFFにする
-jar web-app-01/target/web-app-01.jar
Zipkinでの出力結果は下記のとおりであり、WebApp01 -> WebApp02についてのトレーシングできていることが確認できる。
※SerivceNameを指定しているにも関わらず、Zipkin上でUNKNOWN_SERVICEと表示される事象については現在調査中。
検証2：Batchアプリのトレーシング検証(1)
Batchアプリに検証1と同じようにAgentを組み込んだ場合のトレーシング検証である。
Batchアプリのロギング設定にもWebアプリ同様にTraceId、SpanIdを設定している。
また、アプリの起動オプションははWebアプリと同じ設定としている。
Zipkinでの出力結果は下図の通りであり、バッチアプリ側はAPIのGetメソッド実行部分の処理からがトレーシング対象となっており、ジョブの起動から終了までの全体のトレーシングができていないことが確認できる。
検証3：Batchアプリのトレーシング検証(2)
いろいろ検索した結果、opentelemetry-extension-annotationsを利用することで任意のメソッドをトレーシング対象として設定することが判明したので、その方法でトレーシング検証を行う。
まずは、Batchアプリの依存ライブラリにopentelemetry-extension-annotationsを追加する。
<dependency>
<groupId>io.opentelemetry</groupId>
<artifactId>opentelemetry-extension-annotations</artifactId>
<version>1.0.1</version>
</dependency>
その後、BatchアプリでSpanとして計測したいメソッドに@WithSpanを設定する。
- 設定例
import io.opentelemetry.extension.annotations.WithSpan;
//省略
public class SampleJobRunner implements CommandLineRunner {
@WithSpan
public void run(String... args) throws Exception {
final String jobName = System.getProperty("job.name");
log.info("Job Start, JobName:{}.", jobName);
apiCall();
log.info("Job Finished, JobName:{}.", jobName);
}
@WithSpan
private void apiCall() {
//処理は省略
}
}
上記設定後、「検証2：Batchアプリのトレーシング検証(1)」と同じ方法でBatchアプリを起動した結果、下図の通りBatchアプリのrunメソッドからトレーシングされていることが確認できた。
また、Batchアプリのログ、Webアプリのログでは同じTraceIdでログ出力されていることも確認できた。
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e0748955ace7d29e thread:main level:INFO logger:com.example.sample.runner.SampleJobRunner message:Job Start, JobName:sample.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:f60deafc5f7d16a3 thread:main level:INFO logger:com.example.sample.runner.SampleJobRunner message:API Call, URL : http://localhost:8881/web01/sample.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:f60deafc5f7d16a3 thread:main level:INFO logger:com.example.sample.runner.SampleJobRunner message:StatusCode : 200 OK, Header : {Content-Type=application/json, Transfer-Encoding=chunked, Date=Sat, 19 Jun 2021 12:28:24 GMT, Keep-Alive=timeout=60, Connection=keep-alive}.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:f60deafc5f7d16a3 thread:main level:INFO logger:com.example.sample.runner.SampleJobRunner message:Response Message : web01-app-message.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e0748955ace7d29e thread:main level:INFO logger:com.example.sample.runner.SampleJobRunner message:Job Finished, JobName:sample.
2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:fbb222846e9c58bd thread:main level:INFO logger:com.example.sample.JobRunner message:Job Normally Finished, Execution time : 2152ms
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e98db147d1913074 thread:http-nio-8881-exec-9 X-Track: level:INFO logger:com.example.webapp01.Controller message:getSample is Called.
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e98db147d1913074 thread:http-nio-8881-exec-9 X-Track: level:INFO logger:com.example.webapp01.Controller message:Header : {traceparent=00-bc36ac3e733f5cc0f7875b08604fd005-528fff0462f17bbb-01, host=localhost:8881, connection=keep-alive, accept=application/json, application/*+json, user-agent=Java/11.0.2}.
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e98db147d1913074 thread:http-nio-8881-exec-9 X-Track: level:INFO logger:com.example.webapp01.Controller message:API Call, URL : http://localhost:8882/web02/sample.
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:7fad792962413c9e thread:http-nio-8882-exec-8 X-Track: level:INFO logger:com.example.webapp02.Controller message:getSample is Called.
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:7fad792962413c9e thread:http-nio-8882-exec-8 X-Track: level:INFO logger:com.example.webapp02.Controller message:Header : {traceparent=00-bc36ac3e733f5cc0f7875b08604fd005-1930db76decfbcb2-01, host=localhost:8882, connection=keep-alive, accept=application/json, application/*+json, user-agent=Java/11.0.2}.
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e98db147d1913074 thread:http-nio-8881-exec-9 X-Track: level:INFO logger:com.example.webapp01.Controller message:StatusCode : 200 OK, Header : {Content-Type=application/json, Transfer-Encoding=chunked, Date=Sat, 19 Jun 2021 12:28:24 GMT, Keep-Alive=timeout=60, Connection=keep-alive}.
date:2021-06-19 21:28:24 trace:bc36ac3e733f5cc0f7875b08604fd005 span:e98db147d1913074 thread:http-nio-8881-exec-9 X-Track: level:INFO logger:com.example.webapp01.Controller message:Response Message : web02-app-message.