OpenTelemetryのトレースを活用してボトルネックを探す体験をしてみた
OpenTelemetryのトレースを試したい。
標準なデモとしてはOpenTelemetry Demoがあるが、これはフルセットのヘビーなものなので、もうちょっとライトにやりたい。
ということで、OSSのOpenTelemetryトレーサ「Jaeger」に収録されているHotRODというデモで遊んでみた。
基本的に作者Yuri Shkuroのブログ「Take OpenTracing for a HotROD ride」に従っている。
HotRODとは
HotRODは、タクシー配車アプリケーションデモだ。4つ用意されたボタン（カスタマーボタン）のいずれかをクリックすると、「HotROD T763767C arriving in 2min [req: 8819-1, latency: 683ms]」のように表示される。
「T763767C」がドライバーID（ナンバープレートを想像。ダミーなのでランダムに割り振られ、再利用とか全部出払っているとかは考えない）。2minのところも少しランダム性はあるがこれもダミー。このあたりの短縮化や最適化はこのデモの目的ではない。
着目するのはlatency（レイテンシー）。Webのフロントエンドからボタンを押すことで/dispatchのGETリクエストが送信され、マイクロサービスのバックエンドに入って処理されてレスポンスを受け取るまでの時間となる（状態変化するのにGETメソッドなの、というのはともかく）。
処理によってこのlatecyが悪化するので、トレースを見て原因と対策を考えよう、というのがテーマとなる。
環境はDocker化されているので、実行は簡単。
$ git clone https://github.com/jaegertracing/jaeger.git $ cd examples/hotrod $ docker compose up
デモのHotRODとトレーサのJaegerのコンテナがこれで起動する。
Jaegerでトレースを見る
HotRODのWeb UIを操作すると、トレース情報がJaegerに送られる。これにより、HotRODの動作や、latencyを悪化させている箇所を観察できる。
http://localhost:8080 でHotRODアプリケーションを開くと、前出の画面となる。
ボタンを1つクリックして配車した後、Jaegerで様子を見てみよう。http://localhost:16686 で用意されているJaegerを開く。まずは「System Architecture」タブから「DAG」を選ぶと、HotROD内のマイクロサービス間の呼び出し有向非巡回グラフが表示される。
ここから以下のことがわかる。
- frontendサービスから、driver、customer、routeという3つのサービスを呼び出している。driver・customer・routeは互いに独立している
- driverからredis-manual、customerからmysqlを呼び出している
- アーキテクチャをここから予想できる。frontendはWebフロントエンド、driverはRedisと組み合わせたドライバー探索、customerはMySQLにある顧客情報取得、routeは経路探索を担っていると推測される
実際にはredis-manualもmysqlも本物ではなくてダミー実装となっている。
次に、HotRODの画面に戻り、配車情報にある「open trace」をクリックする。これで、/dispatchがリクエストされてから結果を返すまでの一連の流れの中で発生した個々のサービス実行が、スパンの集合体として示される。
縦軸方向でグラフが複数あったら、それは並行実行していることになる。呼び出しによって親子関係のツリーが構成され、子が全部完了するまで親のスパンは終われない。
まずfrontendサービスが受けた後、customerサービスが呼び出され、そこからmysqlへのクエリが行われていることがわかる。
終わったらdriverサービスのFindNearestのコールでredis-manualに対してドライバーの探索が実行される。たいていは短く終わるが、!が付いているのは長く時間がかかっており、何らかのエラーになったものと思われる。直列に順次実行されていき、ドライバー候補を10人発見できるまで続くようだ。
候補を発見したら、routeサービスが呼び出され、経路探索に入る。routeのスパンが同じ時刻に最大3つ存在することから、ドライバー候補10人に対して3並列で経路探索を実行していると推測される。
おそらく、これで到着までの時間が最良だった結果のドライバーが選定され、ドライバーIDと到着までの時間が返される、という仕組みだろうと解析できた。ここまでまだ実装コードは読んでいない。
各スパンをクリックすると、スパンに含まれている各種情報がわかる。たとえばredis-manualの!が付いている理由を探ってみると、ドライバーT746425Cに対してRedisのタイムアウトが発生していることがわかった。
ほかにもJeagerではトレースをいろいろな側面で見ることができる。以下は表形式で処理平均時間を見る例だ。
ボトルネックを探る
たとえば「Rachel's Floral Designs」ボタンを連打すると、latencyがどんどん悪化していくことがわかる（画面では、最初は683msで始まったのが、3619msまでになっていっている）。
悪化している状態での配車について、そのトレースを見てみよう。
mysqlへのSQL SELECTクエリの時間が長いのが一目でわかる。まだコードを見ていないのに、customerサービスのクエリまたはデータベースに何らかの問題がありそうだ、というところまで特定できた。これ以上は計装されていないので、コードを見ることになる。
原因としては、クエリ時にこの用途には本来不要なmutex排他ロックがかかっている（という想定）ので、これを解放する。さらにロック処理がなくなるぶん、クエリ遅延時間はもっと速くなるということにする。
このあたりの処理はHotRODバイナリでフラグ化されているので、docker-compose.ymlを以下のように調整する（-Mでmutex排他ロックをやめる、-D 100msで遅延時間をデフォルトの300msから100msに短縮）。
hotrod:
...
command: ["all", "-M", "-D", "100ms"]
docker compose down、docker compose upで上げ直し、再びボタンを連打してみよう。
latencyの値が安定していることがわかる。またトレースを眺めてみる。
赤枠のボックスは後から手で入れたもので、driverサービスのDriverService/FindNearestが完了して、routeサービスが始まるまでにギャップ（空白期間）がある。上に辿っていくとこの時間はfrontendサービス内部で消費している。また、10人のドライバーの経路探索を3つのrouteサービスワーカープールで処理しており、全体として競合が発生して完了するまでに時間を食っていると予想される。
実際にコードを見てみると、ワーカープールはオプション指定で増減できることになっている。ワーカープールにはもっと余裕があるという前提で、ワーカープールのサイズをデフォルトの3よりも増やして並列度を上げてみよう。たとえば-W 100というオプションで100ワーカーになる。
hotrod:
...
command: ["all", "-M", "-D", "100ms", "-W", "100"]
これで再度実行してみる。
全体のlatencyが向上したように見える。トレースも確認しよう。
routeサービスがすべて並列に実行され、ギャップもなくなった。
アプリケーションが十分に計装されていれば、コードを隅々まで読むことなく、トレースからアーキテクチャを推測できて、原因を絞り込む作業も簡便化されることがよくわかった。
おまけ：Vaxilaにつないでみる
先月末より、Mackerelからトレース機能のVaxilaを利用できるようになっている。HotRODからVaxilaに送信できるようにしてみた。
具体的にはopen traceのクリック先をVaxilaにするためにテンプレートをいじったのと、Vaxilaのエンドポイントにhttps接続をするためにCA証明書を含めたDocker定義を書いた。
まず、改変したテンプレート入りのバイナリビルドと、CA証明書入りDockerイメージを作る。
$ git clone https://github.com/kmuto/jaeger.git $ cd jaeger $ git checkout vaxila $ cd examples/hotrod $ docker compose run --rm gobuild $ docker build -t kmuto:hotrod .
続いてVaxilaのAPIトークンを環境変数に入れた上で、Dockerコンテナを起動する。Jaegerも起動するがここでは特に使っていない（otel-collectorかプロキシを使わないと複数のエキスポータに送れないので、両方に送るのはさぼっている）。
$ export MACKEREL_VAXILA_APIKEY=〜 $ docker compose up
「open trace」でVaxilaのトレースが開くようにしてある。「find trace」でドライバーを探せるようにもしたかったのだが、これは自分の理解が足りなくて今うまく動いていない。早速HotRODからトレースを送ってみる。
SQL SELECTが遅い状態。
ワーカープールが不足して、ギャップの発生や完了までの時間がかかっている状態。
ワーカープールを十分に増やした状態。
