こんにちは！ホワイトプラスのコアシステム開発グループでエンジニアをやっている古賀です。
昨今、オブザーバビリティという言葉を耳にすることが増えましたね。オブザーバビリティとは、システムの状態をどれだけ理解し説明できるかを示す尺度です。
近年のソフトウェアは分散システムに始まり複雑化しているため、挙動を把握するための情報を集めて分析することで、システムを理解できるようにすることが重要です。
このような情報にはメトリクス・トレース・ログがあり、OpenTelemetry はこれらを取得するためのOSSツールです。
この記事では、OpenTelemetry を使ってトレースを取得しようとしている方向けに、色々なケースで取得する方法を紹介します。
前提
言語：Golang 1.20.3
実行環境：GCP Cloud Run
分散トレースの重要性
分散トレース（単にトレースとも呼ばれます）とは、1つのリクエストがアプリケーションを構成するさまざまなサービスによって処理される過程を追跡する方法です。
処理過程のどこで障害が発生しているか、パフォーマスが低下しているかという原因を特定するのに有効です。
トレースを模式図で表現すると以下のようになります。
- 赤枠：HTTPリクエスト
/api/get/all-resourceを受信しレスポンスを返すまでの期間 - 青枠：サービスAを呼び出して結果を返すまでの期間
- 緑枠：サービスAがデータを取得するまでの期間
このように処理過程が視覚化されると、「サービスAがデータを取得する」部分がボトルネックになっていることが分かります。
トレースの構成要素
トレースはスパンによって構成され、特にトレース内の最上位にあるものはルートスパンと呼ばれます。入れ子になっているスパンには親子関係があり、赤枠の子スパンが青枠であり、青枠の子スパンが緑枠という関係になっています。
このような視覚化を行なうために各スパンは以下の情報を保持しています。
- トレースID：トレースを一意に識別するもの。同じトレースIDを持つスパンが同一のトレースに含まれる。
- スパンID：スパンを識別するもの。
- 親ID：親スパンのスパンID。ルートスパンは親IDを持たない。
- タイムスタンプ：スパンが開始された日時。
- 継続時間：スパンが終了するまでにかかった時間。
それでは次に、トレースに必要なこれらの情報をアプリケーションで取得する方法を見ていきます。
OpenTelemetry のセットアップ
まずはトレースデータを取得するために、OpenTelemetryのセットアップを記述します。
import ( "cloud.google.com/go/compute/metadata" "context" cloudtrace "github.com/GoogleCloudPlatform/opentelemetry-operations-go/exporter/trace" "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/propagation" sdkTrace "go.opentelemetry.io/otel/sdk/trace" "log" "net/http" "time" ) func initTracer() error { meta := metadata.NewClient(nil) projectId, err := meta.ProjectID() if err != nil { log.Fatalf("failed to find project ID: %v", err) } exporter, err := cloudtrace.New(cloudtrace.WithProjectID(projectId)) if err != nil { return err } tp := sdkTrace.NewTracerProvider( sdkTrace.WithBatcher(exporter), sdkTrace.WithSampler(sdkTrace.AlwaysSample()), ) otel.SetTracerProvider(tp) otel.SetTextMapPropagator(propagation.TraceContext{}) return nil }
ここで設定している TracerProvider とは Tracer にアクセスするための窓口であり、Tracer はスパンを生成します。スパンを生成したい箇所で TracerProvider から Tracer を取得しスパンを生成します。
OpenTelemetry で収集したデータを視覚化するには、Jaeger, GCP Cloud Trace のようなベンダー固有のものにデータをエクスポートする必要があり、ここでは Cloud Trace で視覚化するための Exporter を設定しています。
セットアップが完了したら、スパンを生成する方法をケース毎に見ていきます。
incoming request
HTTPリクエストを受信しレスポンスを返す処理において、手動でスパンを開始・終了することもできますが、Go では otelhttp パッケージの NewHandler を使って自動で生成することができます。
第一引数に http.Handler、第二引数に生成されるスパンの名前を渡します。
func main() { err := initTracer() if err != nil { log.Fatal(err) } otelHandler := otelhttp.NewHandler(http.HandlerFunc(helloHandler), "helloHandler") http.Handle("/hello", otelHandler) http.ListenAndServe(":8080", nil) } func helloHandler(writer http.ResponseWriter, request *http.Request) { time.Sleep(time.Second * 3) }
上記コードをCloud Run にデプロイした後、APIエンドポイント /hello にアクセスし Cloud Trace を見ると、次のように3つのスパンを確認することができます（スパンが4つに見えますが、最上位のものはトレース全体を表現しているものでスパンではありません）。
helloHandler というスパンが先ほどのコードで生成したものです。一方、hello という名前の2つのスパンは上記のコードとは関係なく、Cloud Run によって自動生成されたものです。
Cloud Run が自動生成したスパンのスパンIDやトレースIDは HTTPリクエストヘッダーに含まれており、otelhttp.NewHandler が生成した otelhttp のハンドラはヘッダーからそれらの情報を抽出してhelloHandlerスパンを生成することで、スパンの親子関係を紐づけています。
outgoing request
今度はHTTPリクエストを発行する側でスパンを生成してみます。
otelhttp パッケージの NewTransport を使って http.Client を組み立ててリクエストを発行することで、こちらも自動でスパンを生成します。
先ほどの helloHandler に http://httpbin.org/get へGETリクエストを投げる関数を次のように追加します（httpbin.org はHTTPリクエストとレスポンスを返してくれるサービスです）。
func helloHandler(writer http.ResponseWriter, request *http.Request) { time.Sleep(time.Second * 3) callAnotherService(request.Context()) } func callAnotherService(ctx context.Context) { request, err := http.NewRequestWithContext(ctx, "GET", "http://httpbin.org/get", nil) if err != nil { log.Fatal(err) } client := http.Client{ Transport: otelhttp.NewTransport(http.DefaultTransport), } resp, err := client.Do(request) if err != nil { log.Fatal(err) } // span ends after resp.Body.Close. resp.Body.Close() }
helloHandler スパンを開始して約3秒後にHTTP GETスパンが開始され、その期間を見るとhttp://httpbin.org/get からレスポンスを受信するまでに約3.8秒かかったと考えられます。
手動でスパンを生成する
上述のように incoming/outgoing リクエストでスパンを自動生成できるため、トレースのためにコードを追加する労力を抑えることができます。
通信を伴わない内部処理を手動でトレースしたい場合は、次のようにしてスパンを生成することができます。
先ほどの helloHandler で内部関数を呼び出すように変更します。関数の最初で Tarcer を取得してスパンを生成し、関数の実行が終わったらスパンを終了します。
func helloHandler(writer http.ResponseWriter, request *http.Request) { time.Sleep(time.Second * 3) callInternalMethod(request.Context()) } func callInternalMethod(ctx context.Context) { _, span := otel.Tracer("otelHttpTracer").Start(ctx, "internalMethod") defer span.End() time.Sleep(time.Second * 1) }
そうすると、helloHandler の子スパンに internalMethod スパンを生成できました。
システム連携
これまでは単一システムでのトレースでしたが、次は2つのシステムが連携する処理をトレースしてみます。 Cloud Run サービスを2つ用意して、以下のようにサービスAがサービスBを呼び出す構成を作ります。
サービスAの実装
サービスAは「outgoing request」の実装とほぼ同じで、リクエスト先をサービスBのエンドポイント https://cloud-run-service-b-sample/hello2 に変更します。
これでサービスAの /hello が叩かれると サービスBの /hello2 が呼び出されます。
func main() { err := initTracer() if err != nil { log.Fatal(err) } otelHandler := otelhttp.NewHandler(http.HandlerFunc(helloHandler), "helloHandler") http.Handle("/hello", otelHandler) http.ListenAndServe(":8080", nil) } func helloHandler(writer http.ResponseWriter, request *http.Request) { callAnotherService(request.Context()) } func callAnotherService(ctx context.Context) { request, err := http.NewRequestWithContext(ctx, "GET", "https://cloud-run-service-b-sample/hello2", nil) if err != nil { log.Fatal(err) } client := http.Client{ Transport: otelhttp.NewTransport(http.DefaultTransport), } resp, err := client.Do(request) if err != nil { log.Fatal(err) } // span ends after resp.Body.Close. resp.Body.Close() }
ポイントになるのが otelhttp.NewTransport で、この処理でHTTPリクエストヘッダーにトレースID・スパンIDをセットしています。 これは、サービスAで生成したスパンとサービスBで生成したスパンを関連付けて、トレースを組み立てられるようにするためです（Context Propagation と呼ばれる概念）。 サービスBではリクエストヘッダからトレースID・スパンIDを抽出してスパンの生成に使用します。
サービスBの実装
サービスBは /hello2 エンドポイントを用意し、2秒間sleepした後にレスポンスを返す hello2Handler を実装します。実装は「incoming request」とほぼ同じです。
func main() { err := initTracer() if err != nil { log.Fatal(err) } otelHandler2 := otelhttp.NewHandler(http.HandlerFunc(hello2Handler), "hello2Handler") http.Handle("/hello2", otelHandler2) http.ListenAndServe(":8080", nil) } func hello2Handler(writer http.ResponseWriter, request *http.Request) { time.Sleep(time.Second * 2) }
otelhttp.NewHandler でリクエストヘッダーに含まれるトレースID・スパンIDを抽出し、新しく生成するスパンに情報をセットしています。
サービスA・サービスBをCloud Run にデプロイし、サービスAの /hello を叩くと以下のトレースを確認できます。
HTTP GET スパンがサービスBの呼び出し元で、その子スパンとしてサービスBの /hello2スパンがあり、その子スパンに hello2Handler スパンができており、サービスAとBで同一トレースとして表示できていますね。
これでリクエスト先の処理の内訳までトレースできるようになったので、システムを横断的に見て、どこでどれだけ時間がかかっているかを理解し易くなりました。
非同期処理
HTTPリクエストではトレース情報を伝播するのにHTTPヘッダーを使いましたが、Cloud Pub/Sub のような非同期処理ではそれが使えません。代わりに、メッセージの属性にトレース情報を含めることで伝播することができます。 Cloud Pub/Sub を使って以下の構成を作って試してみます。
サービスAの/helloにアクセスするとPub/Sub トピックにメッセージを送り、push サブスクリプションを使って非同期的にサービスBの /hello2 を実行します。
サービスAの実装
func helloHandler(writer http.ResponseWriter, request *http.Request) { meta := metadata.NewClient(nil) projectId, err := meta.ProjectID() if err != nil { log.Fatalf("failed to find project ID: %v", err) } client, err := pubsub.NewClient(request.Context(), projectId) if err != nil { log.Fatalf("failed to create Pub/Sub client: %v", err) } defer client.Close() topic := client.Topic("sample") message := pubsub.Message{Data: []byte("payload sample")} message.Attributes = make(map[string]string) // トレース情報をmessage.Attributesに含める propagater := otel.GetTextMapPropagator() propagater.Inject(request.Context(), propagation.MapCarrier(message.Attributes)) // スパンの生成 _, span := otel.Tracer("otelHttpTracer").Start(request.Context(), "publish") defer span.End() messageId, err := topic.Publish(request.Context(), &message).Get(request.Context()) if err != nil { log.Printf("failed to publish message: %v", err) http.Error(writer, "Bad Request: publish message", http.StatusBadRequest) return } }
処理の概要としては、メッセージを組み立ててPub/Sub へ送信し、またPub/Subに送信してからレスポンスを受信するまでの間でpublishスパンを手動生成しています。
ポイントは propagater.Inject(request.Context(),propagation.MapCarrier(message.Attributes)) です。
propagator は propagation.TraceContext であり、これは「OpenTelemetryのセットアップ」のotel.SetTextMapPropagator(propagation.TraceContext{}) で設定したものです。
propagation.TraceContext.Inject で request.Context() に含まれるトレース情報を message.Attributes に詰めています。
サービスBの実装
func helloHandler2(writer http.ResponseWriter, request *http.Request) { body, err := io.ReadAll(request.Body) if err != nil { log.Fatalf("failed to read request body: %v", err) } type PubSubMessage struct { Message struct { Attributes map[string]string `json:"attributes"` } `json:"message"` } data := PubSubMessage{} err = json.Unmarshal(body, &data) if err != nil { log.Fatalf("failed to json.Unmarshal: %v", err) } propagator := otel.GetTextMapPropagator() // メッセージ属性に含まれるトレース情報を context にセットする ctx := propagator.Extract(request.Context(), propagation.MapCarrier(data.Message.Attributes)) // 情報をセットした context を使ってトレースを生成する ctx, span := otel.Tracer("otelHttpTracer").Start(ctx, "subscribe") defer span.End() time.Sleep(time.Second * 1) }
サービスAから送信されたメッセージをリクエストボディから取り出し、その中のトレース情報を抽出し、それを使ってsubscribeスパンを手動生成しています。
こちら側のポイントは propagater.Extract(request.Context(),propagation.MapCarrier(data.Message.Attributes)) です。
propagater は先ほどと同様に propagation.TraceContext で、propagation.TraceContext.Extract でメッセージ属性に含まれるトレース情報を context.Context にセットし、その context を使ってスパンを生成しています。
サービスA・BをCloud Run にデプロイし、サービスAの /hello を叩くと以下のトレースを確認できます。
publishスパンの後にレイテンシが約3秒間あり空白として表現されています。その後、サービスBのsubscribeスパンが生成されていることが分かりますね。
これで非同期処理でも、スパンが生成された場所に関係なくトレースを組み立てることができるようになりました。
最後に
ホワイトプラスでは一緒に働く仲間を募集しています。 カジュアル面談もできますので、お気軽にご応募ください！
