いちばん長いスパンが犯人ではない

一言でいうと

トレースで最も長いスパンを直すのは、たいてい無駄骨です。応答時間を縮められるのは、自己時間が大きく、かつクリティカルパス上にあるスパンだけです。

なぜ必要なのか

注文APIのp50は290ミリ秒でした。トレースを開くと、画面の一番上に158ミリ秒のバーが見えました。在庫の照会でした。2人が3日をかけてその照会にキャッシュを付け、デプロイした翌日にダッシュボードを見ると、p50は289ミリ秒でした。1ミリ秒です。

原因は単純でした。在庫の照会は、価格計算と同時に始まります。在庫の照会が158ミリ秒で終わったとき、価格計算はまだ動いていて、ゲートウェイは両方が終わるのを待ちます。遅く終わるほうが応答時間を決めます。在庫の照会を0にしても、ゲートウェイは相変わらず価格計算を待ちます。

この思い違いは、画面のせいも大きいものです。ウォーターフォール(waterfall)画面はスパンを長さ順に見せ、人の目は一番長いバーに先に行きます。ところがバーの長さは「その区間にどれだけ時間がかかったか」であって、「その区間を縮めれば全体が縮むか」ではありません。2つの問いは別で、2つ目の問いに答えるには計算が必要です。

どう動くのか

答えを出してくれるのは、2つの計算です。

自己時間(self time)は、そのスパンが子に渡さずに直接使った時間です。総時間から、子が占めた時間を引きます。ここで一度つまずくのですが、子の時間を単純に足して引いてはいけません。並列に動く子がいると、合計が親の総時間を超えて、自己時間が負の数になります。子の区間の和集合の長さを引く必要があります。

クリティカルパス(critical path)は、ルートの終わりから逆向きにたどって作ります。今見ている時刻より遅く終わる子は飛ばし、最も遅く終わる子へ下ります。その子が始まった時刻まで上がってきたあと、それより前に終わった兄弟へ移ります。こうするとルートの最初から最後までが隙間なく覆われ、各断片の持ち主が決まります。断片の合計は、ちょうどルートの継続時間と等しくなります。この等式が、計算が合っているかを教えてくれる検算です。

2つの計算を合わせると、順位がひっくり返ります。上の事故で、在庫の照会は総時間1位、自己時間1位でしたが、クリティカルパスへの寄与は0でした。逆に価格ルールの評価は、総時間3位でしたが、クリティカルパスへの寄与が142ミリ秒と圧倒的でした。直すべきは3位でした。

ここにもう1つ加わります。N+1です。同じ名前の兄弟スパンが数十個並んでいると、1つ1つは3ミリ秒なので順位に入りません。ところが16個を足すと45ミリ秒になり、1回のクエリにまとめるとそのうち42ミリ秒が消えます。個々のスパンではなくグループを見ないと見えません。

OpenTelemetryのトレースのドキュメントは、スパンを作業の1単位、トレースをリクエストが通った経路と定義しています。スパンには開始時刻と継続時間、親スパンの識別子が入っていて、クリティカルパスの計算に必要なのはその3つだけです。ツールがなくても、標準ライブラリで計算できるという意味です。

現場での姿

4つのことが繰り返されます。

1つ目、p50とp99でクリティカルパスが違います。普段は価格計算が最後に終わりますが、在庫データベースが止まった瞬間に、在庫の照会が最後になります。p50だけを見て直しても、p99はそのままです。そのため、2つのトレースをそれぞれ取り出して、クリティカルパスを見比べる習慣が必要です。

2つ目、データが汚れています。コレクターが断片を失うと、親がファイルにない孤立スパン(orphan span)が残り、ルートがまるごと抜けたトレースもできます。こうしたトレースを混ぜたまま計算すると、合計が静かに狂います。計算の前に、「ルートが1つで孤立スパンがないトレース」だけを選び出す段階が必ず必要です。

3つ目、計算対象を何件にするかが、結論を変えます。レイテンシは4つのゴールデンシグナルの1つで、その指標を改善するには、どのトレースを代表にするかをまず決める必要があります。トレース1件だけを見てクリティカルパスを決めると、その1件の偶然をボトルネックと誤解しやすくなります。逆に、数千件を平均すると、並列構造が互いに相殺されて、どこも目立たなくなります。現実的な妥協は、同じエントリーポイント(同じルートスパン名)ごとにまとめ、継続時間の分布の代表点をいくつか選んでそれぞれ計算し、経路に入るスパン名が重なるかを見ることです。名前が重なれば構造的なボトルネックで、分かれれば条件によって変わるボトルネックなので、直し方も変わります。

4つ目、予想される削減量を書き残していない改善は、検証されません。「これを直せば速くなりそうだ」は、デプロイ後に確認する方法がありません。直す前に「ルートから142ミリ秒減る」を数字で書いておけば、デプロイ後に合っていたか間違っていたかが残ります。間違っていたなら、モデルが間違っていたということで、それが次の判断を直してくれます。

次のラボですること

Podに入っている3,454個のスパン(150トレース)を、標準ライブラリだけで分析します。親子を再びつないで深さを付け、重なる子を和集合で処理して自己時間を求め、クリティカルパスを計算して、断片の合計がルートの継続時間と等しいかを検算します。そのあと、「最も時間がかかったスパン」のリストと「自己時間の上位」のリストと「クリティカルパスへの寄与の上位」のリストが、互いに違うことを表で確認し、N+1を見つけてまとめたときの削減量を計算します。最後に、p50とp99のトレースのクリティカルパスを見比べ、何を直すかを予想削減時間とともにファイルとして提出します。