🐈

TypeScriptでOpentelemetryを計装したらトレースががっつり欠損してた話

2023/11/18に公開

TypeScript

前置き

TypeScriptで書いているアプリでトレースをCloud Traceにexportしていたのですが、しばらくしてトレースが一部（というかかなり）送れていないことに気づきました。色々と調査した結果、opentelemetry-js側の実装が原因であることが分かりました。

構成は以下の通りです。Cloud Runのマルチコンテナを採用しており、サイドカーのOpentelemetry Collector（以降Collectorと略）を経由してCloud Traceに送っています。ちなみにCollectorではTail Samplingを使用して一定以上のレイテンシのトレースのみサンプリングしています。

計装の仕方について

アプリでは以下のように計装していました。AlwaysOnSamplerを指定して全てのトレースをCollectorに送るようにしつつ、流量の多いアプリなのでBatchSpanProcessorのmaxQueueSizeを50000にまで引き上げています。
（一部コードを省略しています）

const provider = new NodeTracerProvider({
  sampler: new AlwaysOnSampler(),
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: 'service-name',
  }),
});
const exporter = new OTLPTraceExporter({
  compression: CompressionAlgorithm.GZIP,
});
provider.addSpanProcessor(
  new BatchSpanProcessor(exporter, {
    maxQueueSize: 50000,
  }),
);
provider.register();

registerInstrumentations({
  tracerProvider: provider,
  instrumentations: [
    new HttpInstrumentation(),
    new FastifyInstrumentation(),
    new GraphQLInstrumentation({
      depth: 1,
    }),
    new RedisInstrumentation(),
    new PrismaInstrumentation(),
  ],
});

調査と行き詰まり

本番環境に投入してしばらくしてトレースが欠損していることに気付き調査を開始しました。一通り調査した結果、アプリからCollectorにトレースが送れていないことが分かりました。

Tail Sampling Processorを利用している場合デバッグログを有効にするとCollectorが受け取ったトレース件数を出力してくれるのでこの値を見ながら確認しました。

しかしここから送信側、受信側のどちらでトレースが欠損しているかを特定できず調査は行き詰まってしまいました（この時の自分に言ってやりたい。まずは送信側の実装を読めと...）。

解決までの道のり

解決の日は突然やってきました。同僚に「トレース欠損してる問題ってこれ関係あります？」と言われて見たRelease Noteがとても怪しい気配を漂わせていたのです。

🐛 (Bug Fix)
fix(sdk-trace-base): BatchSpanProcessor flushes when maxExportBatchSize is reached #3958 @nordfjord

対象のPRと関連するIssueをまとめると次のように書かれていました。

Batch span processorはデフォルトで5秒間隔で512 batch sizeをexportする実装になっている
他言語のSDKで実装されているようにeager exportingにすべき
現在の実装だとアプリが秒間100個以上のspanを生成するとそのうちmaxQueueSizeを超えてドロップしてしまう

......なんだと。

慌ててexport周りの実装を見てみると確かに秒数間隔でのみexportしており、流量が多くなるとspanがドロップする作りになっていました。

v1.7.1を取り込んだことでトレース欠損の問題は解消しました。問題としてはこれでFixですが、せっかくなのでv1.7.0とv1.7.1の実装をそれぞれ読んでみたので以下につらつらと書いていきます。興味のある方はお付き合いください。

v1.7.0での実装

おおまかな流れとしては次のようになっています。

計装側でspan.end()を呼び出す
_addToBuffer()で_finishedSpansにアプリで生成したspanがpushされる
_maybeStartTimer()で_flushOneBatch()をsetTimeoutの関数として実行する。タイムアウトの時間は_scheduledDelayMillisで設定されておりデフォルトだと5000ミリ秒
_flushOneBatch()で_finishedSpansにpushしたspanから_maxExportBatchSizeで設定したサイズを取り出してexportする
exportが完了すると_maybeStartTimer()が再帰的に呼び出されて再度タイマーがセットされる（=5000ミリ秒後に_flushOneBatch()が実行される）

このように一定間隔ごとに決まったサイズのspanがexportされる実装になっています。そのためアプリで秒間100個以上のspanが生成され続けると_addToBuffer()の以下の部分でドロップするようになります。

v1.7.1での実装

これらの問題があったためv1.7.1では_maybeStartTimer()で_finishedSpansのサイズが_maxExportBatchSizeを上回っている場合は定期実行を待たずにexportを連続で実行するように修正が入りました。

前置き

計装の仕方について

調査と行き詰まり

解決までの道のり

v1.7.0での実装

v1.7.1での実装

Discussion