クライアントが測る時間とサーバーが測る時間

一言でいうと

外へ出ていく呼び出しは、両側で測ります。クライアントスパンとサーバースパンの差がそのまま「サーバーの外で使われた時間」であり、その時間をスパンの境界の中に入れなければ、ユーザーが経験する遅さがトレースに現れません。

なぜ必要なのか

障害対応の会議で最もよくある膠着がこれです。下流チームは「うちのp99は20ミリ秒だ」と言い、上流チームは「うちで測ると300ミリ秒だ」と言います。どちらも自分のダッシュボードを見ていて、どちらも正しいのです。異なる区間を測っているだけです。

サーバーが測っているのは、リクエストハンドラーが開いていた時間です。その前には、接続を得て、リクエストをシリアライズし、バイトを送り、相手のスレッドプールで順番を待つ時間があります。後ろには、レスポンスを受け取ってデシリアライズする時間があります。クライアントからしか見えないこの区間が、ユーザーが実際に待った時間の大部分を占めることが多いです。

さらに悪いのが、コネクションプールの待機です。プールが空いていると、呼び出しを送る前に待つことになりますが、多くの計装は、プールから接続を得たあとでスパンを開始します。そうすると、その待機はどのスパンにも入りません。トレースには30ミリ秒の呼び出しだけが並んでいるのに、ルートスパンは2秒です。人は「空き区間」を見ても原因を見つけられません。

どう動くのか

OpenTelemetryは、外へ出ていく呼び出しにSpanKind.CLIENTを、受ける側にSpanKind.SERVERを使います。この2つは1つのトレースの中で親子としてつながり、同じ論理的な作業を異なる視点から測った1組です。2つのスパンの時間の差を引いてみることが、このラボの出発点です。

境界をどこに置くかが設計の核心です。ルールは1つで書けます。呼び出し側がレスポンスを待ち始めた瞬間から、レスポンスを手にした瞬間までがCLIENTスパンです。接続を得るために待った時間も、リトライの間に休んだ時間も、その中に含まれて初めて、ユーザーが経験した時間と同じになります。リトライは、試行ごとに子スパンを1つ置き、外側のスパンが全体を覆う形が読みやすいです。

切断された呼び出しは、ペアがずれます。クライアントが120ミリ秒で諦めても、サーバーは400ミリ秒を最後まで働きます。すると、同じトレースに120ミリ秒のCLIENTスパンと400ミリ秒のSERVERスパンが一緒に残ります。この形を見分けられないと、「サーバースパンが親より長い」を計装のバグと誤解します。実際には、リソースが漏れているというサインです。誰も読まないレスポンスを、サーバーが作り続けているのです。

キャンセルは、エラーとは別に残す必要があります。ユーザーがタブを閉じて接続が切れたのは、サービスの失敗ではありません。ステータスをERRORに上げると、エラー率がユーザーの行動に応じて上下し、その指標で設定したアラートが明け方に人を起こします。OpenTelemetryのスパンステータス規約は、ステータスをUnset・Ok・Errorの3つとし、エラーに上げるかどうかは計装する側が決めるものとしています。キャンセルは、ステータスをそのままにして、属性とイベントとして残すほうが扱いやすいです。

属性の設計は、カーディナリティの問題です。外へ出ていく呼び出しの宛先を書くとき、アドレスをそのまま入れると、注文IDとPodのサフィックスが値に混ざり込みます。Semantic ConventionsのRPC規約がrpc.serviceとrpc.methodを別々に置いているのは、このためです。どのサービスのどの操作かは値の種類が少なく、だからこそ集計できます。IDは属性の値ではなく、必要なときにイベントやログへ下ろします。

ダンプを使ってクリティカルパスや繰り返し呼び出しを計算する方法は、このパスの別のラボが扱い、出ていくヘッダーに何を載せるかは、認定資格コースのコンテキスト境界ラボが扱います。ここでやることは、その2つの間です。そうした計算が成り立つように、出ていく側にスパンをどこからどこまで引き、何を付けるかです。

最後に、1つのリクエストが同じ宛先を何度も呼ぶことは、クライアントスパンがあって初めて見えます。サーバー側だけを計装すると、下流にスパンが6個散らばっているだけで、それが1つのリクエストから出ていったという事実は、上流のトレースに現れません。宛先と操作を低カーディナリティの属性として付けておけば、同じペアが何回出ていったかを数える作業が、クエリ1行になります。

現場での姿

決済の遅延調査で、こんなトレースを見たことがあります。ルートが1.8秒なのに、子スパンをすべて足しても0.4秒でした。残りの1.4秒は、どのスパンにもありませんでした。原因は、コネクションプールのサイズが2で、1つのリクエストが下流を8回呼んでいたことです。計装が接続を得たあとでスパンを開始していたため、待機時間が丸ごと消えていました。スパンの開始をプール取得の前に移す、3行の変更で、その1.4秒が画面に現れ、そこで初めて議論が「なぜ遅いのか」から「プールを増やすか、呼び出しを減らすか」へ進みました。

別のサービスでは、逆にタイムアウトが問題を隠していました。クライアントのタイムアウトが200ミリ秒なので、ダッシュボードのp99が常に200ミリ秒に張り付いていました。サーバー側のスパンも一緒に見ると、同じトレースに1.2秒のSERVERスパンが残っていました。クライアントは諦め、サーバーは働き続けており、その作業がたまって、あとに続くリクエストをさらに遅くしていました。ペアがずれたスパンの組を数えるクエリ1つが、この悪循環を断つ根拠になりました。

次のラボですること

同じ呼び出しをクライアントとサーバーの両側で測って差を求め、その差を待ち行列時間と残りに分けます。コネクションプールの待機をスパンの外に置いた場合と中に入れた場合を並べて作り、同じことがどれだけ違って見えるかを確認します。タイムアウトで切断された呼び出しのペアを2つのダンプから探して合わせ、キャンセルされた呼び出しをエラーとは別に残すルールを決めます。次に、宛先を識別する属性を低カーディナリティで設計して値の種類を自分で数え、1つのリクエストが同じ宛先を6回呼ぶ様子を、クライアントスパンだけで明らかにします。最後に、そのルールをファイルに書き、2つ目のクライアントにそのまま適用します。