スパンはどこで区切るのか
一言でいうと
スパンは、コードブロックごとに引くものではなく、次にこのトレースを開く人が何を尋ねるかで引きます。少なすぎるとどこを見ればよいかわからず、多すぎると誰も開いて見ません。
なぜ必要なのか
決済が遅いという報告を受けてトレースを開いたら、スパンが1つでした。名前はPOST /checkout、長さは211ミリ秒。ここから読み取れるのは「211ミリ秒かかった」ということだけです。カートの読み込みに時間がかかったのか、決済代行会社が遅かったのか、自分たちのプロセスの中で商品の価格を24回求めるのに時間がかかったのか、わかりません。計装は有効になっていましたが、どんな問いにも答えられない計装でした。
そこで逆に振れたチームもあります。ループの中にスパンを1つずつ入れたところ、1リクエストがスパン30個になり、商品が200個ある注文では200個を超えました。画面には同じ形の棒がどこまでも続き、障害対応の会議でそのトレースを最後までスクロールした人は誰もいませんでした。スパン数は保存コストであると同時に、読む人の注意力の予算でもあります。
2つの失敗は、同じ問いを飛ばした結果です。このリクエストで後から何を尋ねることになるのか、その問いに答えるには境界がどこにあるべきか、という問いです。
どう動くのか
境界を決めるときに使える数字が1つあります。親スパンが生きていた時間のうち、どの子にも覆われていない時間です。この文章では、これを計装の空白と呼びます。子同士が重なりうるので、和集合として測り、親の長さから引くと残ります。
POST /checkout ├────────────────────────────────────────┤ 211ms
cart.load ├──────┤ 30ms
payment.charge ├────────────┤ 60ms
공백 ······· ······ ······ 121ms
空白が大きいということは、遅いという意味ではなく、その区間にまだスパンがないという意味です。この区別は重要です。自己時間とクリティカルパスは、すでに作られたスパンの間で何が遅いかを問う性能計算であり、空白は、まだ計装のない箇所を指し示す地図です。空白を測る目的は順位を付けることではなく、次のスパンをどこに引くかを選ぶことです。
境界を引くときのルールは、3つに整理できます。
| ルール | 意味 | 破った場合 |
|---|---|---|
| プロセス境界には必ずスパンを置きます | 入ってくるリクエストと出ていく呼び出しを分けます | 相手側の問題か自分たちの問題か、切り分けられません |
| 空白が大きい区間を先に分けます | 覆われていない時間が、そのまま「わからない時間」です | スパンを増やしても答えが出ません |
| 繰り返しはスパンにせず、畳みます | 回数・合計時間・最大値にします | 同じ形の棒がトレースを埋め尽くします |
3つ目が、実務で最もよくずれます。繰り返し区間を1つのスパンで包んだうえで、そのスパンにcount、total_ms、max_msを属性として付ければ、スパン1つで繰り返し全体を説明できます。平均だけを残すと、24回のうち1回が10倍遅かったという事実が消えてしまうため、最大値も一緒に残し、その1件が何だったかはイベントとして書きます。イベントはスパン内の一時点に付く記録なので、繰り返しの途中の特定の瞬間を残すのに向いています。
境界の表示にはSpanKindを使います。入ってきたリクエストを処理するスパンはSERVER、プロセスの外へ出ていく呼び出しはCLIENT、プロセス内で分けた区間はINTERNALです。この表示は飾りではなく、あとで「自分たちが待った時間」と「自分たちが使った時間」を分ける基準になります。CLIENTスパンの合計が大きければ他者を待ったことになり、INTERNALが大きければ自分たちが働いたことになります。
最後に、この判断を人の好みに任せたままにすると、レビューのたびにまた争うことになります。リクエストあたりのスパン上限と許容する空白の割合をファイルに書いておき、機械に読ませれば、新しいハンドラーを計装するときに同じ基準が自然に適用されます。上限を超えたからといって常に間違いとは限りませんが、超えた理由を1行書かせるだけでも、「とりあえずスパンを増やしてみよう」はなくなります。
このラボのPodで判定できないことも、はっきりさせておきます。コレクターのバイナリも、トレースを描画してくれるバックエンドの画面も、このPodにはありません。そのため「画面でこのトレースが読みやすいか」は目で見る必要があり、採点ツールが見るのは、スパンをJSONLとして書き出したダンプの構造です。スパン数、親子関係、名前、SpanKind、属性のキー、そして空白の割合です。ミリ秒の絶対値はPodが混雑すると変わるため、割合だけで判定します。
現場での姿
ある注文サービスは、自動計装だけを有効にして数か月を過ごしました。自動計装はHTTPの入口とデータベースドライバーにスパンを作ってくれるため、トレースが空に見えることはありませんでした。ところが、遅いリクエストを開くと、いつも空白が半分でした。その半分はアプリケーションコードが直接動く区間で、自動計装が見られる場所ではありませんでした。空白を測り始めて初めて、「どこに手でスパンを入れるべきか」が一覧として出てきました。
逆の事故もありました。バッチ処理の1つが項目ごとにスパンを作っていましたが、普段は項目が10個なので誰も気づきませんでした。月末に項目が2万個になると、1つのトレースが2万個のスパンになり、収集側がそのトレース1つのせいで詰まりました。直した方法は、スパンを消すことではなく畳むことでした。項目のスパンをなくし、バッチのスパン1つに処理件数と最長所要時間を属性として残しました。トレースは再び読めるようになり、遅かった1件はイベントとしてそのまま残りました。
次のラボですること
計装が1行もない注文処理コードを受け取り、スパン1つだけのトレースから出発します。空白を測って計装のない区間を見つけ、その区間を分けて空白を5%未満に下げます。次に、繰り返し区間をスパンにしてスパンが何個になるかを自分で数え、同じ繰り返しを属性とイベントで畳んで再び減らします。SpanKindで境界を表示したあと、リクエストあたりのスパン上限と許容する空白をルールファイルに書き、そのルールを検査する小さなプログラムを作って、前に作ったダンプに対して実行してみます。最後に、2つ目のハンドラーを同じルールのもとで最初から計装します。