CloudTraceの導入を通して学んだTIPS集

この記事は エムスリーAdvent Calendar 2020の16日目の記事です。

エムスリーエンジニアリンググループの関根（@sekikatsu36）です。 2020年4月よりエムスリーへ参加し、主にSRE業務を担当しています。

エムスリーでは数百のマイクロサービスを開発・運用していますが、マイクロサービスは1つの処理の流れを追跡すること（トレーサビリティ）が難しく、トラブル時の原因特定にコストがかかるという課題があります。 その解決策として分散トレーシングに着目し、GCPのCloudTraceを主要サービスへ導入することを進めてきました。

ここではその活動を通じて得た知見を雑多にご紹介していきます。

例ではJavaを利用します。 また分散トレーシングの実現方法としては、OpenCensus *1 を採用します。

cloud.google.com

「分散トレーシングって何？」という方は、過去に弊社のエンジニアがJJUGに登壇した際の資料がありますので、ぜひご覧ください。

分散トレーシングの実装

OpenCensusのJavaライブラリを使うと、以下のようにSpan*2を記録できます。

try (Scope ignored = Tracing.getTracer()
        .spanBuilder("Spanの名前")
        .setSampler(Samplers.alwaysSample())
        .startScopedSpan()) {
    // 何か処理
}

「OpenCensusをとりあえず使ってみたい！」という場合は、便利なライブラリや実装例の紹介記事がインターネット上に多く存在するため、比較的簡単に実装できると思います。 例えば、私は初めてOpenCensusを触った時にこちらの記事を参考にさせていただきました。

qiita.com

またエムスリーでは、より簡単に実装できるよう、OpenCensusのラッパー m3-tracing を開発しています。OSSなので興味があればぜひご覧ください。そしてあわよくばスターください！

github.com

こちらを利用した場合、例えば以下のようにより短いコードでSpanを記録できます。 サービスをまたがるTraceを作成する際は、後述する通りtraceparentヘッダを自前で処理しなくていいため、特に便利に使えます。

M3Tracer tracer = M3TracerFactory.INSTANCE.get();
try(TraceSpan ignored = tracer.startSpan("spanの名前")) {
    // 何か処理
}

どこでSpanを作るべきか

分散トレーシングでは、時間を計測したい範囲をSpanとして明示的に定義しなければなりません。 もちろん遅くなりそうな場所には全て事前に細かく必要十分に設定しておきたいところですが、それが特定できないから分散トレーシングを使いたいわけで。 分散トレーシングの導入で過剰なコストをかけたりバグを埋め込んでは本末転倒なので、私は以下の方針でSpanを設定しています。

(1) とりあえず他サービスから受け取ったリクエストの開始〜終了にSpanを作る

各サービスでこれを満たしていれば、性能問題が発生した際に、とりあえずどのサービスが原因なのか、即座に判断できます。

大部分の各種のWebフレームワークは、リクエストを受信した時に実行されるFilter機能を備えているので、Trace用のFilterを実装するのが良いと思います。 また、サービスをまたいでTraceを統合するために、traceparent *3 の対応も忘れずに実装します。

弊社の場合、これらの機能を実現するServlet Filterを共通部品として実装しました。m3-tracingに組み込み、複数のサービスで利用しています。

m3-tracing/jvm/servlet at master · m3dev/m3-tracing · GitHub

(2) 他サービスを呼びだすリクエストの開始〜終了にSpanを作る

(1)に追加することで、リクエストが送られてから受け取られるまでの時間もわかるようになり、ネットワークや中間機器、ミドルウェアによる遅延を発見できます。 また、DBやCacheなど、それ自体でSpanを作成できない周辺サービスへの呼び出しにも、余裕があれば追加します。 実例として、あるリクエストが不必要にDBへ何度もアクセスしている、キャッシュを有効に使えていない、などの問題の発見に繋がりました。

他サービスへのアクセスはHttpClientやRepositoryなどライブラリや共通コンポーネントになっていることが多いので、それをラップ or 拡張します。 弊社の場合、SpringのRestTemplateやApache HttpClient、okHttp, p6spy JdbcEventListenerなど、必要になったクライアントライブラリごとに、ラップした共通部品を作っています。

例えばApache HttpClientを使う場合は、以下のようにリクエストの前後にライブラリの実装を挟むことで、Spanの作成、traceparentヘッダの送信、SpanのCloseを実装可能です。

CloseableHttpClient httpClient = HttpClientBuilder.create()
    .addInterceptorFirst((HttpRequestInterceptor) M3TracingHttpInterceptor.INSTANCE)
    .addInterceptorLast((HttpResponseInterceptor) M3TracingHttpInterceptor.INSTANCE)
    .build();

(3) それ以外は性能問題が発生してからSpanを追加する

YAGNI原則に従い、逆に1,2以外の箇所は、必要になってから対応します。 特に問題が起きていないのにSpanを追加してしまうと、導入コストが増える、Spanが多すぎてノイズになる、など、費用対効果が薄くなりがちと考えています。

また、CloudTraceはSpanの数で課金されるため、盲目的にSpanを作ってしまうとCloudTraceの費用に影響が出ます。 単にSpanに情報を足したい場合は、子Spanを新たに作るのではなく、(1)で作成したSpanにAttribute(Tag, Label)やMessageEventを追加するのも有効です。

// 処理別に子Spanを作る方法。無駄にSpan数が増えて高コスト＆ノイズが増える
try(TraceSpan span = tracer.startSpan("panret")) {
    if(flag) {
        try(TraceSpan span = span.startChildSpan("proc a")) {
            // 処理A
        }
    } else {
        try(TraceSpan span = span.startChildSpan("proc b")) {
            // 処理B
        }
    }
}

//時間を計測する必要がないなら、タグをつけた方が見通しが良い
try(TraceSpan span = tracer.startSpan("panret")) {
    span.set("flag", flag)
    if(flag) {
        // 処理A
    } else {
        // 処理B
    }
}

サンプリングレートを設計する

全てのSpanをそのまま記録すると、オーバーヘッドの肥大や利用料金の増加に繋がります。 そのためサンプリングレートを設定して、実際に記録される頻度を減らすのが一般的かと思います。 OpenCensusでは、サンプリングレートをAlways, 浮動小数点(例えば0.1なら10%)、Neverの三つから設定できます。

ここで注意すべきは、複数のサービスをTraceが横断した場合のサンプリングレートです。 例えば サービスAからサービスBにリクエストが送信される時、サービスBのサンプリングレートはサービスAのサンプリングレートに影響を受けます。

サービスAのサンプリングレートがNeverだった場合

サービスAのSpanは一切記録されず、サービスBは自身のサンプリングレートに従ってSpanを記録します。 なお、OpenCensusのライブラリを使う場合、サンプリングレートがNeverであっても、サービスAから送られるリクエストにはtraceparentヘッダが付与されます。

サービスAのサンプリングレートがNever以外だった場合

サービスBがNeverであれば、サービスAのSpanだけ記録されて、まるでサービスBが呼ばれていないように見える、わけではありません。 サービスBでは自身の設定は無視され、親であるサービスAのSpanが記録される場合は同時に記録されます。

そのため、「Spanの生成を抑えるためにサービスBはサンプリングレートを0.01にしよう」というケースでも、サービスAが誤ってAlwaysになってしまうと、引きずられて全Spanが出力されます。 なお、サービスAを経由せず、直接サービスB先にリクエストが飛んだケースでは、当然サービスBのサンプリングレートが直接影響します。

このように、親となる送信元のサンプリングレートを設定する際には注意が必要です。 誤ってrootとなるサービスのサンプリングレートをAlwaysに設定 → 後続のサービスでSpanが全出力 → CloudTraceの利用金額が急騰、みたいな状況にはお気をつけください。 特にrootに近いサービスでは、サンプリングレートを低めに設定しておいて、必要に応じて上げていく方が費用面では安心です。

SpanのCloseし忘れに注意する

分散トレーシングは便利ですが、誤った使い方をするとメイン処理に影響を与えてしまいます。 その1つが、Spanの閉じ忘れ頻発によるメモリリークです。 基本的に try-with-resources ブロックを使っていれば問題ないはずです。が。

Span (スパン名) is GC'ed without being ended.

OpenCensus-Javaの場合、上記のエラーログが出力された場合、どこかにCloseのし忘れがあります。 このケースではGCされているのでセーフですが、Closeが漏れているのは確かなので、潰しておいた方がよさそうです。

CloseableHttpClient httpClient = HttpClientBuilder.create()
    .addInterceptorFirst((HttpRequestInterceptor) M3TracingHttpInterceptor.INSTANCE)
    .addInterceptorLast((HttpResponseInterceptor) M3TracingHttpInterceptor.INSTANCE)
    .build();

例えば、前述した上記のコードには、実はバグがあります。 というのも、Apache HttpClientではリクエストの送信中に例外が発生すると、HttpResponseInterceptorは実行されません。そのためCloseがすり抜けます。

Webフレームワークの制約などで try-with-resources を使えないシーンでSpanを作成する場合は、例外などでCloseできないケースがないか、仕様を確認しましょう。 setRetryHandlerを使えば例外の発生時も処理を拾えます。

CloseableHttpClient httpClient = HttpClientBuilder.create()
    .addInterceptorFirst((HttpRequestInterceptor) M3TracingHttpInterceptor.INSTANCE)
    .addInterceptorLast((HttpResponseInterceptor) M3TracingHttpInterceptor.INSTANCE)
    .setRetryHandler(new M3TracingHttpRequestRetryHandler(new DefaultHttpRequestRetryHandler()))
    .build();

まとめ

非常に簡単にですが、CloudTraceを使っていて得た知見と、開発した m3-tracingについて紹介させていただきました。

今後は新しい規格であるOpenTelemetryもGAし、分散トレーシングはますます盛り上がっていく領域かなと思っています。 分散トレーシングによって課題を発見・解決できた例も社内に増えてきましたので、これからも活用・応用を進めていきたいです。

We are Hiring!

エムスリーでは、データを用いて価値を生み出したいエンジニアを広く募集中です。

データ基盤の管理のみならず、その基盤を使ったシステムの開発や施策の実現など出来ることもたくさんあります。よろしければぜひ以下から応募を検討してみて下さい!

jobs.m3.com

*1:後続の新規格にOpenTelemetryがあります。CloudTraceにて、JavaではまだOpenCensusが推奨クライアントライブラリのため、OpenCenesusを利用しています

*2:処理の1単位。ある処理の開始から終了までに発生したSpanを、ツリー構造でまとめたものがTraceとなる

*3:OpenCensusでは、リクエストの送信時にtraceparentというHTTPヘッダに現在のSpan情報をセットすることで、異なるサービス間でSpanの親子関係を維持します。送信側はtraceparentの作成、受信側はtraceparentの解析が必要です。