Cloud RunのトレースのサンプリングレートはGoogle Cloudに任せよう
はじめに
Cloud Runで構成したNode.jsのアプリケーションへOpenTelemetry（以下OTel）を導入してすべてのトレースをサンプリングしてCloud Traceで表示しようと思ったのですが、期待する挙動になりませんでした。
いろいろ試した結果、サンプリングレートはGoogle Cloudに任せたほうが良さそうという結論に至りました。これはその結論に至るまでの記事です。
もし自分でサンプリングレートをコントロールしたいなら自前のトレースバックエンドを構築する、あるいは特定のリクエストを必ずトレースしたいならOTelのコレクターを介さずX-Cloud-Trace-Contextを使う方法[1]が良さそうです。
構成
Cloud Run
server1とserver2のシンプルな構成です。
server1->server2へリクエストするエンドポイントを作成し、トレースを取るためにこの構成にしました。
OTelとエンドポイントのコード
OTelの実装です。
Metricsの検証もしていたのでいろいろ混ざっていますがご了承ください。
import { NodeSDK } from '@opentelemetry/sdk-node'
import {
PeriodicExportingMetricReader,
ConsoleMetricExporter,
View,
Aggregation,
InstrumentType,
} from '@opentelemetry/sdk-metrics'
import { TraceExporter } from '@google-cloud/opentelemetry-cloud-trace-exporter'
import {
BatchSpanProcessor,
SimpleSpanProcessor,
} from '@opentelemetry/sdk-trace-base'
import { MetricExporter } from '@google-cloud/opentelemetry-cloud-monitoring-exporter'
import { isProduction } from './app'
import { W3CTraceContextPropagator } from '@opentelemetry/core'
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http'
import {
ExpressInstrumentation,
ExpressLayerType,
} from '@opentelemetry/instrumentation-express'
import { WinstonInstrumentation } from '@opentelemetry/instrumentation-winston'
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http'
const traceExporter = isProduction
? new TraceExporter()
: new OTLPTraceExporter()
const spanProcessor = isProduction
? new BatchSpanProcessor(traceExporter)
: new SimpleSpanProcessor(traceExporter)
const exporter = isProduction
? new MetricExporter()
: new ConsoleMetricExporter()
export const openTelemetrySDK = new NodeSDK({
traceExporter,
spanProcessor,
metricReader: new PeriodicExportingMetricReader({
exportIntervalMillis: 10_000,
exporter: exporter,
}),
views: [
new View({
aggregation: Aggregation.ExponentialHistogram(),
instrumentType: InstrumentType.HISTOGRAM,
}),
],
instrumentations: [
new HttpInstrumentation(),
new ExpressInstrumentation({
ignoreLayersType: [
ExpressLayerType.MIDDLEWARE,
ExpressLayerType.REQUEST_HANDLER,
],
}),
new WinstonInstrumentation(),
],
textMapPropagator: new W3CTraceContextPropagator(),
})
openTelemetrySDK.start()
エンドポイントの実装です。
https://<Cloud Runの公開URL>/1へリクエストすると別のCloud Runサービスの/2へリクエストし、一連の処理をトレースするようにしています。トレース情報はHTTPヘッダーにあるのでloggerで出力しました。
import { openTelemetrySDK } from './opentelemetry-sdk'
import express, { Application, Request, Response } from 'express'
import axios from 'axios'
import logger from './logger'
import { errorCounter } from './meter'
const app: Application = express()
app.use(express.json())
app.use(express.urlencoded({ extended: true }))
export const isProduction = process.env.NODE_ENV === 'production'
const server2 = isProduction ? process.env.SERVER2 : 'http://localhost:8000'
app.get('/1', async (_req: Request, res: Response) => {
logger.info('requested to /1', _req.headers)
await axios.get(`${server2}/2`)
return res.status(200).send({ message: 'requested to /1!!!' })
})
app.get('/2', async (_req: Request, res: Response) => {
logger.info('requested to /2', _req.headers)
return res.status(200).send({ message: 'requested to /2!!!' }).end()
})
const port = process.env.PORT || 8000
try {
app.listen(port, () => {
console.log(`Running at Port ${port}...`)
})
} catch (e) {
if (e instanceof Error) {
console.error(e.message)
}
}
const gracefulShutdown = async () => {
console.info('SIGINT/SIGTERM received. Shutting down...')
try {
await openTelemetrySDK.shutdown()
process.exit(0)
} catch (e) {
const instanceName = 'Dynamically retrieve the instance name of cloud run'
console.error('Error during shutdown', e)
errorCounter.add(1, {
environment: 'production',
instance_name: instanceName,
})
process.exit(1)
}
}
process.on('SIGTERM', gracefulShutdown)
process.on('SIGINT', gracefulShutdown)
全体のコードは以下にあります。
このコードをCloud Runへデプロイします。
Google Cloudのtraceparentの謎を追う
https://<Cloud Runの公開URL>/1へ連続してリクエストするとCloud Loggingへ以下のように表示されました。
最初のリクエストのトレースフラグが01(=sampled)で、それ以外は00(=not sampled)でした。
最初だけサンプリングされる理由は、Cloud Runでは1秒あたり最大0.1リクエストのサンプリングレート[2]だからだと思います。
試しに1秒おきにリクエストを投げ続けると、約10秒おきにフラグが01になりました。
トレースの最初にあたる/1へのリクエストにtraceparentが存在する理由は、Google CloudがCloud Runへのリクエストに対して自動的に入力する[3]ためだと思います。
すべてをサンプリングしてみる
server1のOTelのSamplerをalways_onに設定して/1へリクエストすると以下の結果になりました。
/1のtraceparentのtrace_flagsは00ですが、OTelが付与したフラグは01と差分が出ました。/2は差分なしです。
これはtraceparentに対してGoogle CloudとOTelが管理する順番や仕様が原因では？と思ったのですが、以下の認識が間違っていたらご指摘ください🙏
- Google Cloudが/1のリクエストへ
traceparentを付与する（trace_flagsはGoogle Cloudが決定する） - server1のSamplerが
always_onなのでOTelがtrace_flagsを01にする - Google Cloudが
/2のリクエストのHTTPヘッダーを見てtrace_flagsを引き継ぐ - server2のSamplerはデフォルトの
parentbased_always_onなので親スパンのtrace_flagsを引き継ぐ
このように一連のリクエストの途中でtrace_flagsが変わってしまうと、Cloud Traceでキレイなトレースとして見ることができませんでした。
OTelがコントロールする前にGoogle Cloudがtrace_flagsを決定するならば、サンプリングレートを自分たちでフルコントロールするのは難しそうです。
よって、Google Cloudに乗っかるならここのコントロールはIaaS側に任せた方が良さそうという結論に至りました。
なお、OTelのtextMapPropagatorをtraceparentではなくx-cloud-trace-contextにするとどうなるか検証しましたが、結果は同じくサンプリングレートをコントロールすることはできませんでした。
強制的にトレースするには
そのような仕様が背景にあってか、リクエストを必ずトレースする場合はX-Cloud-Trace-Contextを使う方法をGoogle Cloudは推奨しています。
ヘッダーでo=1（TRACE_TRUE=1）を指定してリクエストします。
curl "https://dummy.a.run.app/1" --header "X-Cloud-Trace-Context:105445aa7843bc8bf206b12000100000/1;o=1"
すると一連のリクエストがトレースされました。（なぜかTRACE_TRUE=0でもトレースされました）
おわりに
すべてのリクエストのトレースを収集する目的でサンプリングレートをコントロールしようと思いましたが、Google Cloudの仕様上難しそうです。
ただ、本番環境ですべてのリクエストをトレースすることはあらゆるコストがかかるので現実的ではないと思います。
よって基本はGoogle Cloudにサンプリングをまかせ、つぶさに観察したいリクエストは強制的にトレースするのが良さそうです。
あるいはX-Cloud-Trace-ContextというGoogle Cloudの仕様に乗っかりたくない場合は、traceparentではなくb3を用いて自前で構築したオブザーバビリティバックエンドへエクスポートするのが良いかもしれません。
余談ですが、Google Cloudの1秒あたり最大0.1リクエストのサンプリングレートという仕様は、リクエスト数が急増してもサンプルの数は一定になるはずなので良い設計だなと思いました。
OTEL_TRACES_SAMPLERとOTEL_TRACES_SAMPLER_ARGはリクエスト数に対して適用されるはずで、急増した分サンプル数も増えるはずです。
参考にさせていただいたサイト
- https://dev.henry.jp/entry/cloud-native-opentelemetry
- https://buildersbox.corp-sansan.com/entry/2023/05/15/110000
Discussion