Skip to content

필사 모드: 分散トレーシングが実際に答える問い — スパン、サンプリング、そしてどこで時間が消えたのか

日本語
0%
정확도 0%
💡 왼쪽 원문을 읽으면서 오른쪽에 따라 써보세요. Tab 키로 힌트를 받을 수 있습니다.

はじめに — 遅いという報告は来るのに、どのサービスか分からないとき

決済画面が2秒かかるという報告が来ました。ダッシュボードを開いてみると、ゲートウェイのp99が1.8秒まで上がっています。その後ろにあるサービスは十個で、それぞれのp99をひとつずつ開いてみます。全部正常です。

この状況はよくあります。そしてこの状況で、メトリクスは原理的に答えを出せません。各サービスが個別に速いという事実と、それらを順に通ったひとつのリクエストが遅かったという事実は、互いに矛盾しないからです。必要なのはサービス別の統計ではなく、リクエストひとつの全経路です。

この記事はその経路を作って読む方法を扱います。

トレース、スパン、コンテキスト伝播の構造

トレースはひとつのトレースIDを共有するスパンのツリーです。各スパンは名前、開始時刻、終了時刻、親スパンID、属性、イベント、ステータスを持ちます。そして種類(kind)を持ちますが、これが実務では思ったより重要です。

  • SERVER: リクエストを受け取って処理する側
  • CLIENT: 他のサービスを呼び出す側
  • PRODUCER / CONSUMER: メッセージを送る側と受け取る側
  • INTERNAL: プロセスの中の論理的な区間

CLIENTスパンとSERVERスパンの時間差が、ネットワークとキューイングで消費された時間です。両方のスパンがあってはじめてこの値が分かります。片方だけしか計装されていなければ「呼び出しに時間がかかった」までしか分からず、その理由がネットワークなのか相手のサービスなのかを区別できません。

完成したトレースはこう見えます。

Trace 4bf92f3577b34da6a3ce929d0e0e4736                    計 1,847ms
├─ SERVER    api-gateway   POST /v1/orders                    1847ms
│  ├─ CLIENT    auth-svc     GET /verify                         38ms
│  ├─ CLIENT    checkout     POST /orders                      1782ms
│  │  ├─ SERVER   checkout    POST /orders                     1776ms
│  │  │  ├─ INTERNAL  cart.validate                               6ms
│  │  │  ├─ CLIENT    inventory  GET /stock                      41ms
│  │  │  ├─ CLIENT    pricing    POST /quote                     52ms
│  │  │  ├─ CLIENT    db.query   SELECT coupons WHERE ...      1612ms   <-- ここ
│  │  │  └─ CLIENT    payment    POST /charge                    64ms
│  │  └─ (ネットワーク + キューイング 6ms)
│  └─ INTERNAL  response.serialize                                9ms

コンテキスト伝播はこのツリーを作る唯一のメカニズムです。呼び出す側が現在のトレースIDと自分のスパンIDをヘッダーに入れ、受け取る側がそれを読んで自分のスパンの親とします。標準ヘッダーはW3Cのtraceparentです。

# ゲートウェイが checkout を呼ぶときに実際に出ていくヘッダー
curl -sD - -o /dev/null http://checkout.internal/v1/orders \
  -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01'

# 00                                 バージョン
# 4bf92f3577b34da6a3ce929d0e0e4736   トレースID — リクエスト全体で同一
# 00f067aa0ba902b7                   親スパンID — 呼び出し段階ごとに変わる
# 01                                 サンプリングフラグ — 00 ならこのトレースは保存されない

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

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

トレーシングが必要な理由を「三つ目の信号だから」と説明すると導入は失敗します。正確にどんな問いに答えるのかを知る必要があります。

第一に、ひとつのリクエストがどこで時間を使ったか。メトリクスは集計値なので個別リクエストの経路を復元できません。サービスAのp99とサービスBのp99が同じリクエストのものだという保証はありません。上のトレースで1,612msを使ったクーポン照会クエリは、そのデータベースの平均クエリ時間ダッシュボードには絶対に現れません。一日数百万件のうちこうしたリクエストが1パーセントなら、平均はびくともしません。

第二に、繰り返し呼び出しの問題。N+1クエリはメトリクスに見えません。個別のクエリが4msと速いからです。問題はそれがひとつのリクエストで340回実行されるという事実であり、これはスパンを数えてはじめて見えます。

├─ SERVER  order-api  GET /v1/orders/A-99183                     1421ms
│  ├─ CLIENT  db.query  SELECT * FROM orders WHERE id = ?           5ms
│  ├─ CLIENT  db.query  SELECT * FROM order_items WHERE oid = ?     4ms
│  ├─ CLIENT  db.query  SELECT * FROM products WHERE id = ?         4ms
│  ├─ CLIENT  db.query  SELECT * FROM products WHERE id = ?         4ms
│  ├─ ... (同じクエリ340回) ...

第三に、条件付きの経路。特定のテナント、特定の機能フラグ、特定のキャッシュミスの組み合わせでのみ遅くなる場合です。ログでは各サービスの断面しか見えず、その断面を時刻で突き合わせてつなぐのは推測です。トレースはその組み合わせをひとつのオブジェクトとして見せ、属性でフィルタできるようにしてくれます。

逆にトレーシングが答えられないことも明確です。いつから悪くなったのか、どれだけ多くのユーザーが影響を受けているのかはメトリクスの問いです。そのスパンの中でどんな値を受け取ってどの分岐を通ったのかはログの問いです。トレースは「どこ」に答え、メトリクスは「いつとどれだけ」、ログは「なぜ」に答えます。

計装 — 自動計装の境界と手動スパンを入れるべき地点

出発点は自動計装です。コードを直さずにI/O境界にスパンができます。

npm i @opentelemetry/sdk-node @opentelemetry/auto-instrumentations-node

OTEL_SERVICE_NAME=checkout-api \
OTEL_RESOURCE_ATTRIBUTES=service.version=1.42.3,deployment.environment=prod \
OTEL_EXPORTER_OTLP_ENDPOINT=http://otel-collector.observability:4318 \
OTEL_TRACES_SAMPLER=parentbased_traceidratio \
OTEL_TRACES_SAMPLER_ARG=1.0 \
node --require @opentelemetry/auto-instrumentations-node/register server.js

parentbased_traceidratioは親スパンの決定をそのまま踏襲し、親がないときだけ比率で判断します。これが既定値であるべきです。サービスごとに独立して確率判定をすると、トレースが途中で切れてしまいます。

自動計装が与えてくれるものはちょうどひとつです。ネットワーク境界。HTTPサーバーとクライアント、gRPC、データベースドライバ、Redis、メッセージキューのクライアントが対象です。

自動計装が見られないものもひとつです。プロセスの中で起きるすべてのこと。インメモリのソート、テンプレートのレンダリング、暗号化、シリアライズ、ロック待ち、イベントループの遅延は、どのスパンにも現れません。これらは親スパンのself time、つまり子スパンが占めていない時間としてのみ表れます。

├─ SERVER  report-api  GET /v1/reports/monthly              3204ms
│  ├─ CLIENT  db.query   SELECT ... FROM ledger              412ms
│  └─ CLIENT  s3.upload  PUT report-2026-07.pdf              260ms
│     self time = 3204 - 412 - 260 = 2532ms  <-- 計装されていない区間

self timeが大きいスパンを見つけたら、その中に手動スパンを入れます。入れるべき地点は五か所です。

  1. ループとバッチの境界 — 繰り返し回数を属性として残します。
  2. キャッシュ照会とミス経路 — ヒットしたかどうかを属性として残せば、キャッシュ性能がトレースからすぐ見えます。
  3. 自動計装のないサードパーティSDKの呼び出し
  4. ロック待ち、キュー待ち、コネクションプール待ち
  5. シリアライズ、圧縮、画像処理のようなCPU区間
import { trace, SpanStatusCode } from '@opentelemetry/api'

const tracer = trace.getTracer('checkout', '1.42.3')

export async function applyPromotions(cart, tenantId) {
  return tracer.startActiveSpan('checkout.applyPromotions', async (span) => {
    span.setAttribute('cart.item_count', cart.items.length)
    span.setAttribute('promotion.engine', 'rules-v3')
    span.setAttribute('tenant.id', tenantId)

    try {
      const cached = await rules.fromCache(tenantId)
      span.setAttribute('promotion.cache_hit', Boolean(cached))

      const result = await (cached ?? rules.compile(tenantId)).evaluate(cart)
      span.setAttribute('promotion.rules_evaluated', result.evaluated)
      span.setAttribute('promotion.matched_count', result.matched.length)
      return result
    } catch (err) {
      span.recordException(err)
      span.setStatus({ code: SpanStatusCode.ERROR, message: err.message })
      throw err
    } finally {
      span.end()
    }
  })
}

スパン名は低カーディナリティでなければなりません。GET /v1/orders/A-99183ではなくGET /v1/orders/:idです。バックエンドはスパン名でグルーピングするため、名前にIDが入ると集計ビューが全部崩れます。具体的な値は属性として送ります。

サンプリング — ヘッドサンプリングの罠とテールサンプリングの価値

全量保存はほとんどの組織でコストが合いません。問題は何を捨てるかです。

ヘッドサンプリングはルートスパンを作る瞬間、つまりまだ何も起きていないときに決定します。結果が分からないので無作為に捨てるしかありません。そして無作為に捨てるということは、まれな事象をそのまれさのとおり正確に捨てるという意味です。

python3 - <<'PY'
rate = 0.01              # ヘッドサンプリング1%
errors_per_hour = 5      # 調査したいエラーの実際の発生頻度
kept = errors_per_hour * rate
print(f"保存されるエラートレース: 毎時{kept:.2f}件")
print(f"1件を見るには平均{1/kept:.0f}時間待つ")
PY
# 保存されるエラートレース: 毎時0.05件
# 1件を見るには平均20時間待つ

これがヘッドサンプリングの実質的な結末です。調査が必要なとき、そのトレースはありません。そして残っているトレースは全部正常なリクエストなので、見る理由がありません。

テールサンプリングはトレースが完了するまでスパンをバッファに溜めておき、結果を見て決定します。エラーがあれば残し、遅ければ残し、残りは少量だけ残します。

# otel-collector-tailsampler.yaml
processors:
  tail_sampling:
    decision_wait: 10s
    num_traces: 100000
    expected_new_traces_per_sec: 2000
    policies:
      - name: keep-errors
        type: status_code
        status_code:
          status_codes: [ERROR]

      - name: keep-slow
        type: latency
        latency:
          threshold_ms: 800

      - name: keep-vip-tenants
        type: string_attribute
        string_attribute:
          key: tenant.tier
          values: [enterprise]

      - name: baseline
        type: probabilistic
        probabilistic:
          sampling_percentage: 2

テールサンプリングが無料ではないという点は必ず押さえておく必要があります。三つのコストがあります。

第一に、エージェントからコレクターまでの転送量は減りません。すべてのスパンがコレクターに到着してはじめて判定できるからです。節約されるのはバックエンドの保存とインデックスのコストだけです。コレクター自体のCPUとネットワークはむしろ増えます。

第二に、メモリです。decision_waitの間、すべてのスパンを持っていなければなりません。

python3 - <<'PY'
traces_per_sec, wait_sec, spans, span_kb = 2000, 10, 12, 1.2
mb = traces_per_sec * wait_sec * spans * span_kb / 1024
print(f"バッファメモリはおよそ {mb:.0f} MB (余裕を2倍取ると {mb*2:.0f} MB)")
PY
# バッファメモリはおよそ 281 MB (余裕を2倍取ると 563 MB)

第三に、そしてもっとも多く間違える部分です。同じトレースのすべてのスパンが同じコレクターインスタンスに到着しなければなりません。コレクターを複数台にスケールアウトして普通のロードバランサーを前に置くと、ひとつのトレースのスパンが複数のインスタンスに散らばり、それぞれ断片化したトレースを見て判定します。結果は無作為に切られたトレースです。解法はtrace IDベースのルーティングをするゲートウェイ層を置くことです。

# otel-collector-gateway.yaml — 前段で trace ID によりルーティングする
exporters:
  loadbalancing:
    routing_key: traceID
    protocol:
      otlp:
        tls:
          insecure: true
    resolver:
      dns:
        hostname: otel-tailsampler.observability.svc.cluster.local
        port: 4317

service:
  pipelines:
    traces:
      receivers: [otlp]
      processors: [batch]
      exporters: [loadbalancing]
項目ヘッドサンプリングテールサンプリング
決定時点ルートスパン生成時トレース完了後 decision_wait 経過時
遅いリクエストの保存確率的にのみルールで100%
エラートレースの保存確率的にのみルールで100%
エージェントとネットワークのコストサンプリング比率の分だけ減少減少なし
バックエンド保存コスト減少減少
コレクターのメモリ無視できる毎秒トレース数×待ち時間の分だけバッファ
運用要件なしtrace IDベースのルーティングが必須
設定場所SDKの環境変数コレクターのプロセッサ

実務では二つを組み合わせます。トラフィックが非常に多いサービスはヘッドサンプリングで10~50パーセント水準まで先に減らし、その上にテールサンプリングを載せてエラーと遅いリクエストを拾います。ヘッドですでに捨てたものはテールで復活させられないので、ヘッドの比率は耐えられる限り高く取るのが原則です。

スパン属性と非同期境界 — カーディナリティ、キュー、リンク

「トレースでもカーディナリティに気をつけろ」という助言は半分だけ正しいです。スパン属性の高カーディナリティは、メトリクスの場合と違って爆発の問題ではありません。注文ID、ユーザーID、クエリパラメータは、トレースに入れるためにある値です。それがなければトレースはフィルタできない絵になります。

問題が生じるのは二か所です。

第一に、スパンをメトリクスに変換するときです。spanmetricsコネクターでスパンからREDメトリクスを作ると、ディメンションとして指定した属性がそのままメトリクスのラベルになります。ここにユーザーIDを入れると時系列が爆発します。

connectors:
  spanmetrics:
    # ここに列挙したものだけがメトリクスのラベルになる — 低カーディナリティだけ入れる
    dimensions:
      - name: http.route
      - name: http.request.method
      - name: deployment.environment
    histogram:
      explicit:
        buckets: [10ms, 25ms, 50ms, 100ms, 250ms, 500ms, 1s, 2s, 5s]

第二に、スパン自体のサイズです。OpenTelemetry SDKは既定でスパンあたりの属性個数に上限(既定128)を置きますが、属性値の長さには既定の上限がありません。リクエストボディ全体を属性に入れると、スパンひとつが数百KBになり、転送と保存のコストがそのままついてきます。必要なら明示的に制限します。

OTEL_SPAN_ATTRIBUTE_COUNT_LIMIT=64 \
OTEL_ATTRIBUTE_VALUE_LENGTH_LIMIT=2048 \
node --require @opentelemetry/auto-instrumentations-node/register server.js

非同期境界はもっと厄介です。メッセージキューでは、プロデューサーのスパンがすでに終わったあとにコンシューマーが動きます。親子関係をそのまま使うと親がすでに終了している状態なのでトレースの時間軸がおかしくなり、バッチコンシューマーはそもそも表現できません。メッセージ100個を一度に処理すると親が100個になりますが、スパンは親をひとつしか持てません。

解法はリンクです。

import { propagation, context, trace, SpanKind } from '@opentelemetry/api'

// プロデューサー: メッセージヘッダーにコンテキストを注入する
export async function publish(order) {
  return tracer.startActiveSpan('orders.publish', { kind: SpanKind.PRODUCER }, async (span) => {
    const headers = {}
    propagation.inject(context.active(), headers)
    await producer.send({ topic: 'orders', messages: [{ value: JSON.stringify(order), headers }] })
    span.end()
  })
}

// バッチコンシューマー: 各メッセージのコンテキストを親ではなくリンクとして付ける
export async function consumeBatch(messages) {
  const links = messages
    .map((m) => trace.getSpan(propagation.extract(context.active(), m.headers))?.spanContext())
    .filter(Boolean)
    .map((spanContext) => ({ context: spanContext }))

  return tracer.startActiveSpan(
    'orders.processBatch',
    { kind: SpanKind.CONSUMER, links },
    async (span) => {
      span.setAttribute('messaging.batch.message_count', messages.length)
      await Promise.all(messages.map(handle))
      span.end()
    }
  )
}

メッセージがひとつだけのコンシューマーなら親子でつないでもかまいません。ただしキューの待ち時間が長いと、トレースひとつの継続時間が数時間になってバックエンドで扱いにくくなります。待ち時間の長いパイプラインはリンクで切り、代わりにキュー待ち時間を属性として残すほうが実用的です。

実戦 — トレース画面で実際に何を探すのか

ツールを導入しても使わない最大の理由は、調査の順序がないからです。次の順序がほとんどの場合に通用します。

  1. メトリクスから始めます。どのルートのどの時間帯が悪化したのかを確定します。トレースをやみくもに漁ることから始めると時間だけを使います。
  2. サービスグラフでレイテンシやエラー率が上がったエッジを探します。呼び出し関係そのものが変わったかどうかもここで見えます。
  3. そのルート、その時間帯で継続時間が上位のトレース一覧を見ます。ほとんどのバックエンドが継続時間と属性でフィルタするクエリを提供します。
  4. トレースをひとつ開いてself timeがもっとも大きいスパンを探します。もっとも長いスパンではなくself timeがもっとも大きいスパンです。もっとも長いスパンはたいていルートで情報がありません。
  5. そのスパンの属性を見ます。キャッシュミスなのか、特定のテナントなのか、リトライ回数はいくつか。
  6. 同じtrace IDでログを照会します。ここで「なぜ」が出てきます。

ここでひとつ規律が必要です。遅いトレースをひとつ見て結論を出しません。一件は偶然かもしれません。同じ条件のトレースを複数開いて共通パターンを確認し、正常なトレースと並べて比較します。良いバックエンドはそのためにスパン別の継続時間分布やトレース比較ビューを提供します。

OpenTelemetryが標準化したものと、まだそうでないもの

導入判断に影響するので境界を知っておく必要があります。

標準化されていて安心して寄りかかれる部分は、APIとSDKの構造、OTLP転送プロトコル、W3Cベースのコンテキスト伝播、そしてコレクターです。計装コードをOpenTelemetry APIで書いておけば、バックエンドを変えてもコードを直すことはほとんどありません。HTTPのような中核領域のセマンティック規約も安定しました。

一方で依然として動いている部分もあります。いくつかのドメインのセマンティック規約はまだ実験段階だったり名前が変わっている途中だったりし、言語別SDKの成熟度の差も大きいです。スパンからメトリクスを作る方式やサービスグラフの生成ロジックはバックエンドごとに違い、トレースを問い合わせる言語にも標準がありません。この領域に依存するダッシュボードとアラートは、バックエンドに縛られると考えて設計する必要があります。

おわりに — トレーシングは「どこ」に答える道具である

覚えておくべきことは一文です。トレーシングはリクエストひとつがどこで時間を使ったのかに答える道具であり、その答えはコンテキストが切れておらず、そのトレースが捨てられていないときにだけ存在します。

だから導入の順序も決まります。まず伝播を確認します。トレースがサービス境界で切れているなら、他のすべての投資は無意味です。次にサンプリングを見ます。ヘッドサンプリングだけを使っているなら、調査が必要な瞬間にトレースがないので、テールサンプリングとtrace IDルーティングを一緒に導入します。最後にself timeが大きい区間に手動スパンを入れて、自動計装の空白を埋めます。

まず最初にやることは、今プロダクションでトレースをひとつ開いてみることです。サービスが十個あるのにスパンが三つしか見えないなら、それが来週やるべきことのすべてです。

さらに掘り下げるための資料です。

현재 단락 (1/215)

決済画面が2秒かかるという報告が来ました。ダッシュボードを開いてみると、ゲートウェイのp99が1.8秒まで上がっています。その後ろにあるサービスは十個で、それぞれのp99をひとつずつ開いてみます。全部...

작성 글자: 0원문 글자: 10,818작성 단락: 0/215