PPAPで学ぶDaggerによる非同期処理をZipkinで確認

java

前回、Daggerで非同期処理をやってみました。
PPAPで学ぶ、Daggerによる非同期処理 - きしだのはてな
ただ、こういうログでの実行結果を見せられて、ほら非同期になってるでしょって言われてもよくわからないと思うので、Zipkinで見てみます。


Zipkinは、GoogleのDapper論文を参考にTwitterが開発してオープンソースにした分散トレースシステムです。
http://zipkin.io/

Zipkinの導入

Docker環境があれば、Dockerで立ち上げるのが簡単だと思います。

docker run -d -p 9411:9411 openzipkin/zipkin


NetBeansにDockerを登録しているなら、NetBeansから起動すると便利


直接起動する場合でも、jarを起動するだけなので、そこまで面倒ではないです。

wget -O zipkin.jar 'https://search.maven.org/remote_content?g=io.zipkin.java&a=zipkin-server&v=LATEST&c=exec'
java -jar zipkin.jar


ブラウザから9411ポートでアクセスすると、Zipkinの画面が開きます。

Zipkinにデータを投入

JavaからZipkinにデータを投げるには、Braveというライブラリを使います。いまちょうどバージョン4になっているところなので、ドキュメントがよくわかんないことになってますが、ここではMavenで使えるバージョン3を使います。
BraveはZipkinに限らず使えるトレースログ出力ツールなので、Zipkinに出力するためのzipkin-sender-urlconnectionも必要になります。
io.zipkin.brave:brave-core:3.16.0
io.zipkin.reporter:zipkin-sender-urlconnection:0.6.9
のふたつがdependencyに必要です。

<dependency>
    <groupId>io.zipkin.brave</groupId>
    <artifactId>brave-core</artifactId>
    <version>3.16.0</version>
</dependency>
<dependency>
    <groupId>io.zipkin.reporter</groupId>
    <artifactId>zipkin-sender-urlconnection</artifactId>
    <version>0.6.9</version>
</dependency>


まずReporterを用意します。endpointのURLは、Zipkinのホスト:ポートに「/api/v1/spans」をつけたものです。

String dockerEndpoint = "http://126.0.56.103:9411/api/v1/spans";
URLConnectionSender sender = URLConnectionSender.create(dockerEndpoint);
try (AsyncReporter<Span> reporter = AsyncReporter.builder(sender).build()) {
    ...
}


サービス名とReporterを指定してBraveオブジェクトを生成します。

Brave brave = new Brave.Builder("ppap main").reporter(reporter).build();


呼び出し側がクライアント、受け取り側がサーバーという扱いなので、まずはClientTracerを用意します。
また、Zipkinでは処理区間をSpanとして扱いますが、これはクライアント側で生成します。

ClientTracer clientTracer = brave.clientTracer();
SpanId spanId = clientTracer.startNewSpan("async ppap");


処理を投げる前にsetClientSent()、処理が終わって結果をうけたらsetClientReceived()を呼び出すと開始時刻や経過時間が記録されます。

clientTracer.setClientSent();
System.out.println(ppap.get());
clientTracer.setClientReceived();


処理を受けた側では、ServerTracerを用意して、受け取ったSpanを現在のSpanとして登録します。そして、今回はここで新しいSpanを作成するためにClientTracerを用意します。

Brave brave = new Brave.Builder(name + " task").reporter(reporter).build();
ServerTracer serverTracer = brave.serverTracer();
serverTracer.setStateCurrentTrace(spanId, "ppap span");
//serverTracer.setServerReceived();
ClientTracer clientTracer = brave.clientTracer();
clientTracer.startNewSpan(name);
clientTracer.setClientSent();
...
clientTracer.setClientReceived();
//serverTracer.setServerSend();

本来ならserverReceivedで始めてserverSendで終わる感じなのですけど、Zipkin上の数字がちょっと変になったので、ここではコメントアウトしています。
実際には、各フレームワークに対応したインターセプターなどが用意されているので、ServerTracer/ClientTracerを意識することはあまりないと思います。


ソースコードはこんな感じに。
https://github.com/kishida/dagger_sample/blob/zipkin/src/main/java/kis/daggerSample/AsyncPPAP.java
https://github.com/kishida/dagger_sample/blob/zipkin/src/main/java/kis/daggerSample/AsyncPiko.java


これで実行すると、Zipkinにデータが送られます。時間を設定してクエリーを投げてみます。


クリックすると呼び出し状況が表示されます。

penが終わると、appleが終わる前にpenPineappleが実行開始していることがわかります。また、appleが終わるとapplePenが、そしてapplePenとpenPineappleが終わるとpenPineappleApplePenが実行開始していることがわかります。

遅延を取り除く

Zipkinのグラフを見ると、appleが終わってapplePenが始まるまでなど、すべての処理の前に どうもタイムラグがあるので、原因を探ってみます。
NetBeansプロファイラで確認してみると、Braveのbuilderで時間がかかってるようです。


ということで、Braveの生成をあらかじめ行っておきます。
こんな感じで。
https://github.com/kishida/dagger_sample/commit/5627daed73fa326a403c3c57dd6b2a701047a2ae
実際の利用時には、Braveオブジェクトはサーバー起動時に用意するだけなので、パフォーマンスの問題にはならないと思います。あくまで、分散トレースであって、１台のマシンでのパフォーマンスはNetBeans ProfilerなりVisual VMなりのプロファイラを使いましょうという感じですね。


これで試してみると、タイムラグがなくなって、依存関係が見やすくなっています。