Orchestrionの自動計装でDatadogのトレースが爆発した話

最終更新日： 投稿日：

目次

こんにちは、ヌーラボの中村です。Backlogのファイル・Git・Subversion関連機能の開発やメンテナンス、その他諸々をやっています。本記事では、Git機能のサブシステムにDatadog APMを計装したときに遭遇した問題についてお話しします。

今回話す部分の構成

BacklogのGit機能は、過去記事でも紹介したように複数のマイクロサービスで構成されています。今回はそのうち、HTTPでgit操作を処理する経路について取り上げます。

この構成には、後の話に関係してくる特徴が2つあります。

1つ目は、APMの計装対象がGit HTTP以降であることです。前段のELBとnginxは計装しておらず、Git HTTPの上流からトレースコンテキストが届くことはありません。つまりGit HTTPのスパンは必ずトレースのルートになります。

2つ目は、サービス間の通信が gRPC Stream であることです。git cloneやgit pushで送受信されるpackデータはStreamに乗って流れ、1回の操作で数千のメッセージフレームが行き来します。

また、各サービスはGo言語で実装されており、計装には Orchestrion によるコンパイル時の自動計装を採用しました。ソースコードにほぼ手を入れずにnet/httpやgRPCなどの計装を注入できる仕組みで、デフォルトでは dd-trace-go が提供する全integrationが一括で有効になります。

導入自体は簡単だったのですが、今回踏んだ問題はいずれもこの「自動計装のデフォルト挙動」に起因するものでした。

トレースの混在

問題

本番環境でAPMを有効化したところ、奇妙なトレースが大量に観測されました。無関係な複数のリクエスト（異なるUA、異なるリポジトリに対する操作）のスパンが、同一のtrace_idを共有しているのです。ひどいときは1トレースあたり数千スパンを超える巨大な混在トレースが多数存在し、リクエストが追えない状態になってしまっていました。

容疑者: 二重計装

仮説

混在したトレースを眺めてまず目についたのは、1つのHTTPリクエストに対してserver spanが二重にできていることでした。外側に component: net/http、内側に component: gorilla/mux のスパンが重なっています。

Git HTTPは標準ライブラリの net/http に加えて、パスのワイルドカード処理のためにgorilla/mux を利用しています。Orchestrion のデフォルトでは全integrationが有効になるため、net/http と gorilla/mux の両方が計装され、1リクエストを二重にトレースしていたのでした。

この時点では、「二重計装がアクティブなスパンの管理を狂わせ、後続のリクエストがトレースを引き継いでしまっているのではないか」という仮説を立てました。

対応

orchestrion.tool.go でOrchestrionの設定を変更しました。「全integrationの一括有効化」から「必要なintegrationだけを明示的にimportする」にすることで、gorilla/muxのintegrationを外しました。

  • 変更前（コメントは省略）
//go:build tools

package tools

import (
    _ "github.com/DataDog/orchestrion"
    _ "github.com/DataDog/orchestrion/instrument" // integration
)
  • 変更後（コメントは省略）
//go:build tools

package tools

import (
    _ "github.com/DataDog/orchestrion"

    _ "github.com/DataDog/dd-trace-go/v2/ddtrace/tracer"
    _ "github.com/DataDog/dd-trace-go/v2/profiler"

    _ "github.com/DataDog/dd-trace-go/contrib/net/http/v2"
    _ "github.com/DataDog/dd-trace-go/contrib/google.golang.org/grpc/v2"
    _ "github.com/DataDog/dd-trace-go/contrib/database/sql/v2"
    _ "github.com/DataDog/dd-trace-go/contrib/aws/aws-sdk-go-v2/v2/aws"
    // gorilla/mux は意図的に import しない
)

この対応で二重スパンは消え、スパンはすっきりしてきました。しかし、トレースの混在は解消しませんでした。

犯人: GLSリーク

数珠つなぎのスパン

前述の通りこの構成ではGit HTTPがトレースのルートになるため、Git HTTPのserver spanは全て parent_id:0 になるはずです。ところが実際は、一部のserver spanに非ゼロのparent_id が付いていました。

混在トレースの中のスパンを時系列に並べてみると、「数珠つなぎ」になっていました。あるリクエストのspan_idが、次のリクエストのparent_idになっているのです。

01:40:02  POST /git-upload-pack    span_id=A  parent_id=0
01:40:03  POST /git-receive-pack   span_id=B  parent_id=A
01:40:04  GET  /info/refs          span_id=C  parent_id=B

...（同様の連鎖が14スパン続く）

同一のコンテナ上のリクエストが、1つ前のリクエストのスパンを親として次々にぶら下がっていく。この形が原因特定の大きなヒントになりました。

OrchestrionのGLS

Goには「現在のトレースコンテキスト」をスレッドローカル変数のように暗黙に持ち回る仕組みがないため、トレースコンテキストは context.Context で明示的に引き回すのが普通です。しかし自動計装では、contextを引き回せない箇所でもスパンの親子関係を繋ぐ必要があります。そこでOrchestrionはGLS（goroutine-local storage）を使います。スパンを開始すると現在のgoroutineのGLSスタックにスパンがPushされ、Finish() でPopされます。contextからスパンを取れなかったとき、GLSがフォールバックとして参照されます。

別goroutineでのFinishによるGLSリークのメカニズム

原因は、gRPC integrationの実装パッケージ（contrib/google.golang.org/grpc/v2）の StreamClientInterceptor にありました。この実装は、streamのスパンを開始した後、Finish() を別のgoroutineで呼びます。

// contrib 内部（要旨）

go func() {
    <-stream.Done()
    finishWithError()
}()

Finish() の中のGLS Popは「現在のgoroutineのGLSスタック」への操作なので、Popは別goroutine側で空振りします。その結果、Push元であるserve goroutine（HTTPリクエストを処理している側）のGLSスタックにはスパンが残留します。

これがトレース混在に至るまでの流れは次の通りです。

  1. Git HTTPの git-upload-pack / git-receive-pack 処理はstreaming gRPCを呼ぶため、これらを含むリクエストのたびにserve goroutineのGLSに残留エントリが1件積まれる
  2. net/httpのサーバはHTTP/1.1 keep-aliveの同一コネクションを同じgoroutineで処理し続けるため、次のリクエストも同じserve goroutine上で動く
  3. 本来なら上流ヘッダが無いので新規rootになるはずのスパンが、GLSフォールバック経由で残留エントリを親として拾ってしまい、前のリクエストのトレースにぶら下がる

先ほどの「数珠つなぎ」は、このフローがkeep-aliveコネクション上で繰り返された結果だったわけです。

後からわかったことですが、cross-goroutineでのGLSリークはOrchestrion側でも既知のissueとして登録されており、dd-trace-go側にも下記のコメントが残っています。

// TODO: handle cross-goroutine context values

実際に、gRPCのintegrationだけを無効化したビルドをdev環境で動かして観測すると、全トレースが parent_id:0 となり、トレースの混在が消えることも確認できました。

対応

シンプルな解法ですが、gRPCのintegrationを無効化し、gRPCクライアント呼び出し箇所に手動でスパン計装を入れる形にしました。手動計装は tracer.StartSpanFromContext でスパンを開始し defer span.Finish() で閉じる実装とし、GLSのPushとPopを同一goroutine内で完結させました。

1つ注意が必要だったのは、integrationを外すと後段サービスへのトレースコンテキスト伝播も一緒に消えることです。gRPCのintegrationはスパン生成と同時に、送信するgRPC metadataへ x-datadog-trace-id などの伝播ヘッダを注入してくれていました。そこで、contribの実装を参考にトレースコンテキストをgRPC metadataに注入するclient interceptorを自作しました。

この対応によって、トレースの混在が解消しました。かなり大変な戦いでした……

Streamによる大量スパン

問題

トレース混在と並行して、別の原因によるトレースの爆発も発生していました。

Git ProxyとGit RPCのstreaming RPC（PostUploadPack など）で、1つのstreamあたり数千スパンが生成されていました。

原因

gRPC contribの StreamServerInterceptor は、デフォルト設定（traceStreamMessages=true）だとstream上の SendMsg / RecvMsg 1回ごとに grpc.message スパンを生成します。手動計装であればオプションで無効化できるのですが、Orchestrionの自動計装はinterceptorをオプション無しで挿入するため、このデフォルトがそのまま適用されます。

冒頭で触れた通り、gitのpack streamは1 RPCに数千のメッセージフレームが流れる構造です。Git ProxyとGit RPCそれぞれに送信・受信のスパンが発生するため、スパン数が膨れ上がります。（トレース混在の対応前は、Git HTTPからのStreamスパンもありました）

対応

GLSリークの対応と同様、gRPC のintegrationを外して自作interceptorを使った手動計装に切り替えました。メッセージ単位の情報までは不要と判断し、1 RPCにつき1つの grpc.server スパンだけを生成するようにしました。

同様の実装になったため、自作interceptorは内部の共通ライブラリにまとめています。

補足: orchestrion.tool.go の管理について

今回の対応によって、自動計装の方式が「Orchestrion によって生成された全部入り」の形から、「明示的に選んだものだけ＋手動計装」の形に変わりました。この経緯を知らずに orchestrion.tool.go を編集したり、自動生成の状態に戻したりしてしまうと、問題が再発するだけでなく手動計装と自動計装による二重計装が発生してしまいます。

これを避けるために、lint を追加しました。下記のように、入るとまずい設定を弾くような内容です。

lint-instrumentation:
    @if grep -nF \
        -e '"github.com/DataDog/dd-trace-go/contrib/gorilla/mux' \
        -e '"github.com/DataDog/dd-trace-go/contrib/google.golang.org/grpc/v2"' \
        -e '"github.com/DataDog/dd-trace-go/orchestrion/all' \
        -e '"github.com/DataDog/orchestrion/instrument"' \
        orchestrion.tool.go; then \
      echo "ERROR: forbidden instrumentation import in orchestrion.tool.go"; \
      exit 1; \
    fi

まとめ

紆余曲折ありましたが、最近やっと計装が完了しました。

今までは各サブシステム間のログを独自に発行したTrace IDで紐付けて調査していましたが、今はDatadog上で全ての処理が繋がって見えるようになりました。

最後に、今回の教訓をまとめます。

  • 自動計装は導入コストが低い一方で、デフォルトの挙動が自分のワークロードに合うとは限りません。今回は「keep-aliveで長寿命なコネクション」「数千フレームが流れるstream」という特性が、ことごとくデフォルトと相性が悪い方向に働きました
  • 原因調査ではシンプルな定量指標（今回は parent_id:0）を先に立てたことが効果的でした
  • 合わない部分だけ手動計装に切り替えるのは現実的な落とし所ですが、認知負荷が上がってしまいます。lint等で機械的に保証するところまでやって完成といえます

同じように OrchestrionでGoのマイクロサービスを計装する方の参考になれば幸いです。

souichinakamura

souichinakamura

souichinakamura

souichinakamura

「Backlog」の関連記事

ブログ一覧へ