メトリクスでは答えられない問い

一言でいうと

各サービスが個別に速いという事実と、それらを順番に通過した1つのリクエストが遅かったという事実は、互いに矛盾しません。

なぜ必要なのか

決済画面に2秒かかるという報告が入ります。ゲートウェイのp99は1.8秒に上がっています。後ろにある10個のサービスのp99を1つずつ開いて見ると、すべて正常です。

この状況で、メトリクスは原理的に答えを出せません。メトリクスは集計値なので、個別のリクエストの経路を復元できないからです。サービスAのp99とサービスBのp99が、同じリクエストのものである保証はありません。必要なのは、サービスごとの統計ではなく、リクエスト1つの全体の経路です。

どう動くのか

トレースは、1つのトレースIDを共有するスパンのツリーです。各スパンは、名前、開始・終了時刻、親スパンID、属性、そして種類(kind)を持ちます。種類が実務で重要です。SERVERは受け取る側、CLIENTは呼び出す側です。CLIENTスパンとSERVERスパンの時間差が、ネットワークとキューイングで消費された時間で、両方なければ、その値はわかりません。

このツリーを作る唯一のメカニズムが、コンテキスト伝播です。標準のヘッダーはW3Cのtraceparentで、形式は次のとおりです。

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             ^버전 ^트레이스 ID(32hex)            ^부모 스팬 ID(16hex) ^샘플 플래그

このコードブロックの韓国語コメントは、左から順に、バージョン、トレースID(32桁の16進数)、親スパンID(16桁の16進数)、サンプルフラグを指す、という意味です。

トレースIDはリクエスト全体で同じで、スパンIDはホップごとに変わります。この2つの規則を守るだけでも、ログをトレースIDで結合でき、それだけでも半分は解決します。

トレーシングが答える質問は3つあります。1つ目は、1つのリクエストがどこで時間を使ったのか。1日に数百万件のうち1%だけが、クーポンの取得で1,612msを使っているなら、平均のダッシュボードはびくともしません。2つ目は、繰り返し呼び出しの問題。個別のクエリが4msと速くても、1つのリクエストで340回実行されれば1.4秒です。これはスパンを数えなければ見えません。3つ目は、条件付きの経路です。特定のテナント、特定のフラグ、特定のキャッシュミスの組み合わせでだけ遅くなる場合です。

現場での姿

伝播が途切れる箇所は、ほぼ決まっています。自動計装が包めなかった独自のHTTPクライアント、作業をスレッドプールやワーカーに渡すコード、メッセージキュー、そしてヘッダーを消すサードパーティのプロキシです。トレースが妙に短ければ、この4か所から見ます。

自己時間(self time)という概念も、知っておく価値があります。1つのスパンの全体の継続時間から、子スパンの時間を引いた値です。ここが大きければ、自動計装が見られないプロセス内の作業、つまりシリアライズ、ソート、圧縮が隠れているという意味です。

トレーシングをすべて組み込む前でも、少なくとも相関IDは入れてください。リクエストの入口でIDを作り、すべてのログにそのフィールドを入れ、すべての下位呼び出しのヘッダーに載せて送ることです。これだけで、障害の調査時間が劇的に減ります。

サンプリングをどう決めるのか

すべてのリクエストのトレースをすべて保存すると、コストが賄えません。そのため、一部だけを残しますが、どう選ぶかが、トレーシングの価値をほぼ決めます。

最も単純な方法は、リクエストが入ってくるときに、決められた割合でサイコロを振ることです。実装が簡単で、コストを予測できますが、決定的な弱点があります。遅かったリクエストや失敗したリクエストも、同じ確率で捨てられます。調べたいのは、まさにそのリクエストなのに、です。1%でサンプリングすると、問題のあるリクエスト100件のうち1件しか残りません。

そこで出てきたのが、リクエストが終わった後で残すかどうかを決める方式です。トレースが完成するまで少し溜めておいて、遅かったりエラーがあったりしたら残し、そうでなければ捨てます。欲しいものだけを正確に残せますが、代償があります。トレース全体を覚えていなければならないので、コレクター側にメモリと状態が必要で、そのコレクターが規模に応じて複数台になると、同じトレースのスパンが同じコレクターに行くように経路を合わせなければなりません。

実務では、たいてい両方を混ぜます。基本は低い割合にして、平常時の様子を得て、エラーや遅いリクエストは無条件に残します。そして、決定はリクエストの先頭で一度だけ下して、その結果をヘッダーで伝播します。サービスごとに別々にサイコロを振ると、トレースが途中から途切れて、どこにも使えない断片が残ります。traceparentの最後のフラグが担っているのが、まさにこれです。

もう1つ決めておくべきものが、保持期間です。トレースはログよりも量が多いので、長く置くのが難しくなります。その代わり、トレースから取り出した指標は長く残せるので、原本は数日だけ置いて、サービスごと・経路ごとの遅延の分布は指標として取り出して長期保管する組み合わせが無難です。数か月前との比較という質問には指標が答え、今このリクエストがなぜ遅かったのかにはトレースが答えます。

次のラボですること

3段のチェーンサービスを起動して、traceparentを自分で作って伝播します。形式を検証し、ホップごとにスパンIDが変わるかを確認し、3つのサービスのログをトレースIDで結合し、伝播が途切れた地点を見つけ出し、最後に最も遅い区間と自己時間を計算します。