はじめに
こんにちは、Stackdriver担当者です。いま出張でアメリカ西海岸に来ていますが、時差ボケで破滅しています。
GCPUG Stackdriver Day January 2019でStackdriverを使った分散トレースにログを埋め込む話をしたんですが、スライドだけだともったいないと言われたのでブログの記事にもしておこうかと思います。
OpenCensusとはなにか
そもそもOpenCensusを知らないという人もまだ多いと思うので、まずそこから紹介します。OpenCensusは分散アプリケーションのメトリクスとトレースを取得するためのライブラリ群です。
分散トレースのライブラリは各種APMサービスがそれぞれクライアントライブラリを出していますが、OpenCensusが特徴的なのは、TraceやStatsを取得する部分と、取得されたデータをバックエンドに送信する部分(exporter)が別れているので、バックエンドを切り替える際もexporterのインスタンスの初期化だけ書き換えれば動作するようになっていることです。また自分で独自のexporter(例: 標準出力に記録するだけのexporter)を書くこともできます。
現在 OpenCensus をサポートしているAPMツールはこちらに一覧として載っています。
また今後の方向性としては OpenCensus Agent を通じてデータを送信するように変更し、これによって OpenCensus Agent 側で exporter を切り替えるだけでバックエンドが変更できるようになり、切り替えのためにソースコードを変更しなくて良くなるようにしていく予定になっています。
Stackdriver Trace
Stackdriver Trace は Google Cloud Platform が提供する APM (Application Performance Management) ツールの一つですが、特に分散アプリケーションのトレース(分散トレース)を主力機能として提供しています。Stackdriver Trace はクライアントライブラリとして OpenCensus を利用するように推奨しています。推奨しているということは当然 exporter もあります。
OpenCensusを使ってStackdriver Traceを利用する場合、Goではinstrumentationは次のようになります。
Stackdriver Trace のタイムライン内にログを埋め込む
上のサンプルのように各アプリケーション(例えばGKEクラスタで動かしている各サービス)で Trace と exporter の設定をしてからリクエストを投げてやると、次のような形で分散トレースを生成できます。
これでもマイクロサービス内のどこで処理時間がかかっているか簡単にわかりますが、このタイムラインの中で各Span(各サービスで行われる処理のまとまり)内で起きたイベントを確認できると便利そうです。Stackdriver Trace では Stackdriver Logging へ送信された構造化ログの中に次の2つのフィールドに適切な値が入っていた場合、そのログを Stackdriver Trace の中に表示させることができます。
logging.googleapis.com/trace
logging.googleapis.com/spanId
これら2つのフィールドに必要な Trace ID および Span ID はそれぞれHTTPヘッダやgRPCの特殊フィールドに埋め込まれていて、通常は OpenCensus のライブラリがよしなに取得できるようにしてくれています。再び Go の例で書けば次のような操作で取得できます。
func (ap *arrayParseServiceServer) Parse(ctx context.Context, pr *pb.ParseRequest) (*pb.ParsedArray, error) { span := trace.FromContext(ctx) sc := span.SpanContext() l := logger.WithFields(logrus.Fields{ "logging.googleapis.com/trace": sc.TraceID.String(), "logging.googleapis.com/spanId": sc.SpanID.String(), }) ... }
GKEではStackdriver Logging のエージェントが自動設定されるので、標準出力に構造化ログを出力するだけで Stackdriver Logging に送信されます。上記のフィールドに正しい値が入ったログが Stackdriver Logging に送信されると、Stackdriver Trace がそのログの中にある Trace ID と Span ID をトレースに紐づけ、タイムライン内に表示します。(タイムライン右上に [Show/Hide Logs] というボタンが表示され、ログの表示/非表示を切り替えられるようになります。)
またタイムライン内のログをクリックすると、画面右下に構造化ログ全体が表示されます。
この機能はGAEを使っていた方にはおなじみだったかもしれませんが、GKEを使っている場合においてもちょっと手を加えるだけで使えるようになるので、GKEで分散トレースを考えている場合にはぜひ利用してみてください。
参照
- Configuring the Agent | Stackdriver Logging | Google Cloud
- Stackdriver Logging用の構造化ログの特殊フィールドについて記載があります
- [shared] 20190115 Advanced Distributed Tracing with Stackdriver Trace - Google スライド
- GCPUGで使ったスライドです
- GitHub - ymotongpoo/stackdriver-trace-log-demo: Sample of the correlation between Stackdriver Trace and Stackdriver Logging
- 簡単なサンプルを書きました