自動計装がくれるのはネットワーク境界一つだけだ

一言でいうと

自動計装を有効にして得られるのは、ちょうど1つ、ネットワーク境界です。HTTPのサーバーとクライアント、gRPC、DBドライバー、Redis、メッセージキューのクライアントにスパンができます。プロセスの中で起きることはどのスパンにも現れず、親スパンのself timeという空白としてだけ見えます。

なぜ必要なのか

計装に失敗するチームは、ほぼ同じやり方で失敗します。コードに手動スパンを仕込むところから始めて、2週間後にはスパンが300個あるのに、トレースは相変わらずサービス境界で途切れている状態になります。うまく機能する順序は決まっています。

順序	やること	飛ばすと
1	自動計装を有効にして、データが届くことを確認する	以降のデバッグがすべて推測になります
2	リソース属性を確定する	あとから変えると過去のデータとつながらなくなります
3	サービス境界をまたぐ伝播を検証する	スパンを増やしてもトレースが断片化します
4	self timeが大きいスパンにだけ手動スパンを入れる	自動計装の空白が永遠に残ります
5	加工とサンプリングをコレクターへ移行する	ポリシーを変えるたびに全サービスを再デプロイすることになります

順序3が順序4より前に来る点が核心です。伝播が切れた状態で手動スパンを足すのは、断片化したトレースをさらに細かく断片化することです。

どう動くのか

自動計装を有効にすると、次のようなトレースが出ます。

SERVER    checkout-api   POST /v1/orders                       1421ms
├─ CLIENT    GET http://auth.internal/verify                      31ms
├─ CLIENT    SELECT carts WHERE id = ?                             6ms
├─ CLIENT    redis GET promo:rules:t-8871                          2ms
├─ CLIENT    POST http://payment.internal/charge                  74ms
└─ (나머지 1308ms 는 어떤 스팬에도 속하지 않음)

最後の行がすべてです。自動計装は、どこが問題ではないかを1,308msの空白で教えてくれます。その空白がself timeで、手動スパンはここにだけ入れます。

自動計装が絶対に見えないものは次のとおりです。プロセス内のCPU作業(シリアライズ・圧縮・テンプレートのレンダリング・暗号化)、ロック待ちとコネクションプール待ち、GILの競合とイベントループの遅延、計装パッケージがないサードパーティSDKの呼び出し、そしてビジネスロジックの分岐です。

手動スパンを入れる場所は5か所です。

ループとバッチの境界(繰り返し回数を属性として残します)
キャッシュの参照(ヒットしたかどうかを属性として残すと、キャッシュ効率がトレースからすぐ見えます)
計装パッケージがないサードパーティSDKの呼び出し
ロック、キュー、コネクションプールの待ち
CPUを長く使う処理(シリアライズ、圧縮、レポート生成)

入れると、先ほどの空白が次のように埋まります。

├─ INTERNAL  checkout.apply_promotions                          1298ms
│  ├─ INTERNAL  promotion.load_rules   cache.hit=false           1241ms  <-- 여기
│  └─ INTERNAL  promotion.evaluate     evaluated=812               54ms

守るべきスパン名のルールは1つだけです。名前は低カーディナリティでなければなりません。GET /v1/orders/A-99183ではなくGET /v1/orders/:idにし、具体的な値はすべて属性に入れます。バックエンドはスパン名でグループ化してレイテンシの統計とサービスグラフを作るため、名前にIDが入ると、その集計ビュー全体が崩れます。

リソース属性はあとから直せません。スパン属性と違い、リソース属性はそのプロセスが出力するすべてのシグナルに付き、service.nameを変えた瞬間に、ダッシュボード・アラート・サービスグラフ・過去データとのつながりがすべて切れます。

属性	例	変更できるか
`service.name`	checkout-api	実質的に不可
`service.namespace`	commerce	難しい
`service.version`	2.7.1	デプロイのたびに変わる
`deployment.environment.name`	prod	不可
`service.instance.id`	Pod名	再起動のたびに変わる

ここでよく間違えるものが2つあります。1つ目は、環境属性の名前はdeployment.environment.nameだということです。昔の名前deployment.environmentはもう使われておらず、名前が違うと2つの別々の属性になり、ダッシュボードの変数はそのうち片方しか読みません。2つ目は、service.nameはデプロイ単位ではなくサービス単位だということです。カナリアをcheckout-api-canaryと呼んだ瞬間に、サービスグラフに幽霊ノードができます。

サンプラーは、最初はparentbased_always_onで始めることをお勧めします。最初から比率サンプリングを有効にすると、トレースが見えないときに、計装の問題なのかサンプリングのせいなのか区別できません。比率に移るときも、必ずparentbased_traceidratioを使います。親の判断に従わず、サービスごとに独立して確率判定を行うと、トレースが途中で切れてしまいます。

現場での姿

計装がアプリを壊す形は、いくつかのパターンの繰り返しです。

症状	原因	対応
デプロイ後にメモリが増え続ける	バックエンドの遅延でエクスポーターのキューが満杯になる	キューの上限を明示し、コレクター経由に切り替える
スパンが一部しか届かない	終了時にflushせずにプロセスが終了する	shutdownを呼び出し、終了までの猶予時間を延ばす
1つのスパンが数百KBになる	リクエスト本文全体を属性に入れている	属性値の長さに上限を設定する
サービスグラフに幽霊ノードが出る	カナリアを別のservice.nameでデプロイしている	service.nameはサービス単位で固定する

属性値の長さには、SDKのデフォルトの上限がありません。属性の個数はデフォルトで128個に制限されますが、値の長さは無制限なので、リクエスト本文がそのまま入ると、送信と保存のコストがそのまま跳ね返ってきます。明示的に上限を設定しておくほうが安全です。

次のラボですること

/root/otca-sdk/の下にSDKの環境変数ファイルを書き、リソース属性を規約に合わせて決め、KubernetesのDownward APIでPod名とネームスペースを注入するDeploymentを作って実際に適用します。最後に、スパン名の一覧を整理し、IDが入った名前を検出するリンターを自分で作成します。