[OpenTelemetry 検証2] Grafana × Alloy × Tempo を使用してテレメトリデータを収集しトレース情報を見てみる
はじめに
[OpenTelemetry検証1] ローカル検証環境を立てるまで の続きです。
内容
早速見ていきます。
まずは http://localhost:3000 で Grafana GUI にアクセスし、左側のメニューから Traces を選択します。
初回表示の時点ではおそらく何も表示されていないはずですが、検証用途としていくつかリクエストを送信するとこのような画面になります。
上記は GET, POST, 正常系、異常系のリクエストを計15件送信した結果になるのですが、画面中央の Traces の箇所に 15 と表示されていることがわかります。
ほか、Trace Service には今回検証用で立ち上げた article-server や、上記リクエストそれぞれに要した時間 (Duration) が記録されていることもわかります。
この状態で、Trace Name にある http-server を選択すると以下のようにトレースの詳細を確認することができます。
http-server (423.71µs)
└── ArticleUsecase.GetByID (73.67µs)
└── ArticleRepository.FindByID (11.83µs)
のように、3つの span が階層表示されていることがわかります。
各 span をもう少し詳細に見てみます。
これらを1つずつ見ていくと以下のような構成になっています。
1. http-server (423.71µs)
Trace 全体の親にあたる span です。この配下に後述する子 span が紐づく形になります。
今回は OTEL の SDK を利用して計装しているわけですが、以下のように otelhttp.NewHandler で Wrap するだけで自動的に生成される span です。
Grafana で確認できる属性 (client.address, http.request.method, http.response.status_code..) は SDK 側で自動付与したものです。
otelHandler := otelhttp.NewHandler(mux, "http-server")
2. ArticleUsecase.GetByID (73.67µs)
こちらは手動で作成した span であり、名前の通り Usecase というビジネスロジックの特定の範囲内のみの span です。
前述した http-server の span から wrap されており、かつこの子 span 自体も後述する repository (いわゆるDB操作にあたる処理) を wrap しています。
このように計測したい範囲を特定することで、例えば Query 操作に時間がそこまでかかっていないにも関わらず、この span だけやたら長い。つまり意図していない実装が隠れている。といった原因切り分けなどができるようになります。
エラーメッセージからすぐに特定できない場合などに、ひとまず原因切り分けを目的としてこのような span を入れてみる、みたいなことは運用中にもしばしば発生することが多いです。
3. ArticleRepository.FindByID (11.83µs)
こちらは今回のケースでは一番末端の span です。2の usecase の span から wrap されているものです。
今回は usecase layer から呼び出される repository layer 側 (DBや外部通信など) のみに限定した span を想定しています。
repository 内にいくつかロジックで利用するメソッドを入れるケースが多いかと思うのですが、そのメソッド単位でどれが一番のボトルネックになっているか、などを特定することに使用したりします。
※例: FindByID (pkからビジネスロジックに必要なデータを取得) はそこまで時間がかかっていないのに、FindByCategoryID だけなぜか遅い (indexが適切に設定されてない？)
今回は特に外部通信やDBなどは使わずに全て mock で動作させているためかなり高速で処理されているのですが、これらの結果から以下のようなことが明らかになります。
| 区間 | 時間 | 割合 |
|---|---|---|
| DB 処理 (repository) | 11.83µs | 約 3% |
| usecase (DB 以外の処理) | 61.84µs | 約 15% |
| http-server (usecase 以外) | 350.04µs | 約 82% |
- DB 処理自体は全体の 3% しかない。
- http-server スパンの大半の時間は usecase を呼ぶ前後 (HTTP パース・レスポンス書き込みなど) に費やされている。
おわりに
これで trace の設定などができました。
なお、今回の検証用途の構成では、テレメトリデータの収集・変換・転送を Alloy が引き受ける構成にしています。
Alloy は OTLP を介して それらの情報を Tempo に保存する構成になっていますが、この他に stdout ログ を Loki に保存する構成にしています。
次回はこのログの部分に焦点を当てて検証をしていきたいと思います。