Traceを見ると、どのリクエストが遅かったかは分かります。CPU Profileを見ると、どの関数がCPUを使っていたかは分かります。

では、Traceで見つけた遅いSpanから、そのSpanの処理中に採取されたCPU Profileを直接開けるでしょうか。

この記事では、Go標準のpprofをOpenTelemetry CollectorでOTLP Profilesへ変換し、ProfileのSampleとTrace/SpanをLinkで関連付けます。最終的にはGrafanaで GET /cpu-heavy のSpanからPyroscopeのFlame graphを開き、CPUを使っていた main.countPrimes まで辿ります。

flowchart LR
  App[Go application] -- OTLP Traces --> Collector
  App -- Go pprof Pull --> Collector
  Collector -- OTLP Traces --> Tempo
  Collector -- OTLP Profiles --> Pyroscope
  Tempo --> Grafana
  Pyroscope --> Grafana

固定バージョンのローカル環境でデータの流れを検証したものです。動作は確認できましたが、性能、セキュリティ、バージョンアップを含む本番運用までは評価していません。

検証時の主なバージョンは次のとおりです。

コンポーネント バージョン
OpenTelemetry Collector Core / Contrib 0.158.0
Pyroscope 2.2.0
Tempo 3.0.2
Grafana 13.1.2
Go 1.25

OpenTelemetry Profilesとはなにか

Profileは、一定時間のプログラム実行を観測し、どの関数がCPUやメモリを使っていたかを集計したデータです。

CPU Profileでは、実行中のコールスタックを定期的にサンプリングします。4秒間Profileを採取した場合、データは概念的に次のようになります。

Profile(4秒間のCPU計測結果)
├─ Sample A
│  ├─ stack: main.countPrimes → main.burnCPU
│  └─ value: CPU時間
├─ Sample B
│  ├─ stack: runtime.gc
│  └─ value: CPU時間
└─ Sample C
   ├─ stack: main.countPrimes → main.burnCPU
   └─ value: CPU時間

Sampleは、Profileを構成する観測データの単位です。同じスタックとlabelを持つ複数回の観測は、1つのSample entryへまとめられることがあります。Sampleごとに、少なくとも次の情報を持ちます。

  • どの関数呼び出し経路だったか
  • どの程度CPU時間などを消費したか
  • どの属性が付いているか
  • どのTrace/Spanと関連するか

OTLP Profilesは、こうしたProfileをOpenTelemetry共通のデータモデルで表し、OTLPでCollectorやバックエンドへ送るための仕組みです。

Profiles
├─ Dictionary
│  ├─ StringTable
│  ├─ FunctionTable
│  ├─ StackTable
│  └─ LinkTable
└─ ResourceProfiles
   └─ ScopeProfiles
      └─ Profile
         └─ Samples

文字列、関数、スタック、LinkなどをDictionaryへまとめ、Sampleからindexで参照します。同じ情報をSampleごとに繰り返さずに済む構造です。

GoのSDKの対応はどうか

検証時点の公式OpenTelemetry Go SDKには、Profiles signalのAPI/SDKはありません。Go SDKが担当するのはTrace/Spanの生成とTrace ID/Span IDの管理で、CPU Profileの採取やOTLP Profilesの生成ではありません。

OpenTelemetry Go SDK
├─ Trace/Spanを生成する           ○
├─ Trace ID/Span IDを提供する     ○
├─ CPU Profileを採取する           ×
├─ OTLP Profilesを生成・送信する   ×
└─ Profile SampleへLinkを設定する  ×

CPU Profileの採取にはGo標準の runtime/pprof を使えます。

runtime/pprof
├─ CPUスタックをサンプリングする  ○
├─ Sampleへlabelを付ける           ○
├─ OTLP Profilesへ変換する         ×
└─ OTLP ProfilesのLinkを作る       ×

そこで、OpenTelemetry Go SDKが作ったSpanのIDを、pprof labelとして処理中のgoroutineへ付けます。

実装について

HTTPリクエストごとに、OpenTelemetryが生成したTrace ID/Span IDをContextから取得し、pprof labelとしてリクエスト処理中のgoroutineへ設定します。ここではCPU Profileを開始せず、Collectorがpprof endpointをPullしている間に採取されたSampleへ相関情報を付加します。 対象のhandlerを、pprof labelを設定するhandlerと otelhttp.NewHandler で包みます。

func tracedAndProfiledHandler(
	serviceName, profileMode, spanName string,
	handler http.HandlerFunc,
) http.Handler {
	profiled := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		labelValues := []string{
			"service.name", serviceName,
			"profile_mode", profileMode,
		}

		if profileMode == "pprof-link" {
			spanContext := trace.SpanContextFromContext(r.Context())
			if spanContext.IsValid() {
				labelValues = append(labelValues,
					"otel.profile.trace_id", spanContext.TraceID().String(),
					"otel.profile.span_id", spanContext.SpanID().String(),
					"otel.profile.span_name", spanName,
				)
			}
		}

		labels := pprof.Labels(labelValues...)
		pprof.Do(r.Context(), labels, func(ctx context.Context) {
			handler.ServeHTTP(w, r.WithContext(ctx))
		})
	})

	return otelhttp.NewHandler(profiled, spanName)
}

pprof.Labels はkey/valueの集合を作り、pprof.Do はcallbackの実行中だけそのlabelを現在のgoroutineへ適用します。CPU Profilerがこの処理を実行中のgoroutineをサンプリングすると、コールスタックやCPU時間とともにTrace ID/Span IDがSampleのlabelへ記録されます。

これらのlabelはCollector側でSample属性として取り出され、後段のprocessorによってProfiles Linkへ変換されます。

OTLP ProfilesのLinkとは

ProfilesのLinkは、Profile SampleがどのTrace/Spanに対応するかを表します。

ProfilesDictionary.LinkTable[1]
  trace_id: <16 bytes>
  span_id:  <8 bytes>

Profile.Sample
  stack_index: 1
  link_index:  1

Sampleの link_index: 1 は、「このSampleは LinkTable[1] のTrace/Spanに対応する」ということを表現しています。Linkに含まれるのはTrace ID/Span IDだけで、Trace本体は含まれません。Trace本体は、別のTraces pipelineを通してTempoなどのトレースバックエンドへ送信します。

1回のpprof Pullは数秒間続きます。その間には複数リクエストが実行されるため、1つのProfile内に異なるSpanのSampleが混在します。

Profile(4秒間)
├─ Sample A → Span 111
├─ Sample B → Span 222
├─ Sample C → Linkなし
└─ Sample D → Span 111

Profile全体へ1つのSpan IDを付けると、どのSampleがどのリクエストに対応するのか分からなくなります。そのため、Sampleごとにlabelを読み、正しいLinkを設定する必要があります。

pprof labelをProfiles Linkへ変換する

今回使用したpprof receiverは、pprof labelをSample属性へ変換しますが、その属性からProfiles Linkを作成する処理は行いません。そこで本検証では、独自の profilelink processorをGoで実装し、OpenTelemetry Collector BuilderでカスタムCollectorへ組み込みました。profilelinkは今回作成したもので標準Collectorに含まれるprocessorではありません。

processorは、受信したProfilesの階層を辿って全Sampleを一度ずつ処理します。

ResourceProfiles
└─ ScopeProfiles
   └─ Profile
      └─ Sample

Sample属性からTrace ID/Span IDを取り出した後、同じIDの組み合わせがLink tableにあるかを確認します。

key := linkKey{traceID: traceID, spanID: spanID}
linkIndex, ok := linkIndices[key]
if !ok {
    link := links.AppendEmpty()
    link.SetTraceID(traceID)
    link.SetSpanID(spanID)

    linkIndex = int32(links.Len() - 1)
    linkIndices[key] = linkIndex
    created = append(created, key)
}

sample.SetLinkIndex(linkIndex)

linkIndices は、Trace ID/Span IDの組とLink table上のindexを対応させるMapです。同じSpanに属するSampleが複数あっても、Link entryは1つだけ作って共有します。

LinkTable
├─ [0] empty sentinel
├─ [1] Trace=aaa, Span=111
└─ [2] Trace=aaa, Span=222

Samples
├─ Sample A → LinkTable[1]
├─ Sample B → LinkTable[2]
└─ Sample D → LinkTable[1]

CollectorのProfiles pipelineでは、pprof receiverの直後へprocessorを置きます。

service:
  pipelines:
    profiles:
      receivers: [pprof/cpu]
      processors: [profilelink]
      exporters: [otlp_grpc/pyroscope, debug/profiles]

処理を終えたProfile全体は p.next.ConsumeProfiles(ctx, profiles) で次のコンポーネントへ渡され、最終的にOTLP ProfilesとしてPyroscopeへ送られます。

検証する

検証に使用したコードは、GitHubリポジトリで公開しています。

ローカル環境は次のコマンドで起動・検証できます。

make case-d
make verify-d

verify-d では、同じTrace ID/Span IDについて次を照合します。

  1. アプリのHTTPレスポンス
  2. Tempoへ保存されたTrace
  3. Collectorが生成した Profile.Sample.link
  4. PyroscopeのTrace ID selector
  5. PyroscopeのSpan ID selector
  6. Flame graphに含まれる main.countPrimes

GrafanaではTempoから GET /cpu-heavy のTraceを開き、対象Spanの Related profiles を選びます。

TempoのSpan IDで絞り込まれたPyroscopeのFlame graph 左側で選択したTraceからPyroscopeを開くと、右側のOptionsへSpan IDが入り、Flame graphで main.countPrimes を確認できる

画面右上のPyroscope queryでは、サービス名に加えてSpan IDが指定されています。

labelSelector: {service_name="otel-profile-demo"}
spanSelector:  [対象のSpan ID]

ここでは、Grafanaの画面遷移とProfileデータ上の関連付けを分けて考える必要があります。

Grafanaが対象Span IDを使ったqueryを組み立てられるよう、Spanへ pyroscope.profile.id 属性を設定しています。

trace.SpanFromContext(r.Context()).SetAttributes(
    attribute.String(
        "pyroscope.profile.id",
        spanContext.SpanID().String(),
    ),
)
Grafanaの導線
  Span属性 pyroscope.profile.id

  spanSelectorを組み立てる

Profileデータ上の関連付け
  Profile.Sample.link

  Pyroscopeが該当Sampleを返す

注意点

この経路を本番へ持ち込む場合は、少なくとも次を検討する必要があります。

  • CPU Profileはサンプリングなので、短いSpanは採取窓から外れることがある
  • リクエスト単位のTrace ID/Span IDは高カーディナリティになるのでSample数、転送量、保存量が増える可能性
  • Profiles関連のAPIとコンポーネントは変化するため、Collectorとバックエンドの互換性を確認する
  • 大量のSampleを扱う場合、processorの処理時間、メモリ、ログ量を計測する

今回の検証スクリプトは、pprofのPull窓と対象リクエストが重ならなかった場合にリクエストを再試行します。また、Collectorのdebug出力だけに頼らず、processorのLink生成ログとPyroscopeのselectorも照合しています。

まとめ

公式OpenTelemetry Go SDKはTrace ID/Span IDを生成できますが、GoのCPU ProfileをOTLP Profilesとして出力し、SampleへSpanのLinkを付ける機能は持っていません。 今回の構成では、それぞれの役割を次のように分けました。

OpenTelemetry Go SDK
  → Server SpanとTrace ID/Span IDを生成

Go runtime/pprof
  → CPU Profileを採取
  → IDをsample labelとして保持

Collector pprof receiver
  → pprofをOTLP Profilesへ変換
  → labelをSample属性へ変換

profilelink processor
  → Sample属性からProfiles Linkを生成

Pyroscope / Grafana
  → Span IDに対応するSampleをFlame graphとして表示

pprofをOTLP Profilesへ変換できることと、Profileを特定のSpanへ直接関連付けられること2つは別の処理です。 今回はSample単位のLinkを作ることで、Traceで遅いエンドポイントを選び、その処理中にCPUを使った関数まで辿れることを確認できました。

参考資料


この記事は Zenn にも転載しています。