Posted inデータベース

データベース・オブザーバビリティ：OpenTelemetryでSQLクエリとアプリケーショントレースを紐付ける

Database tutorial - IT technology blog
Database tutorial - IT technology blog

スローログだけでは不十分な理由

PostgreSQLのスロークエリログを凝視しながら、どの特定の関数が問題の SELECT 文を実行したのかを推測して過ごした夜は数えきれません。単純なモノリス構成であれば、通常はテーブル名から推測できます。しかし、50以上のサービスと数百のエンドポイントが存在するマイクロサービス環境では、その推測は通用しません。4.8秒もかかっているクエリを見つけたとしても、それが重要な「チェックアウト」リクエストによるものなのか、それとも重要度の低いバックグラウンドの「アナリティクス」ジョブによるものなのかは判別できないのです。

MySQL、PostgreSQL、MongoDBを大規模に運用してきた経験から、これらすべてに共通するもどかしい制限があることに気づきました。それは、データベースはアプリケーションのコンテキストに関しては「ブラックボックス」であるということです。標準的なログは、何が実行され、どれくらい時間がかかったかは教えてくれます。しかし、誰がそれを開始し、なぜそれが発生したのかを教えてくれることはほとんどありません。

データベース・オブザーバビリティ（観測性）は、これを変えます。分散トレーシングのための OpenTelemetry (OTel) と、メタデータ注入のための SQLCommenter を組み合わせることで、サーバーに到達する SQL クエリにアプリケーションレベルのトレースを直接結びつけることができるようになります。

解決策：SQLCommenterとトレースコンテキスト

従来のモニタリングは、CPUのスパイクやメモリ圧迫などのインフラストラクチャメトリクスに焦点を当てていました。オブザーバビリティはそれとは異なり、コンテキスト（文脈）が重要になります。OpenTelemetry は、リクエストがサービス間を移動する様子を追跡します。通常、その可視性はリクエストがデータベースドライバに到達した瞬間に途切れてしまいます。データベースエンジンは、Python や Go のバックエンドに存在する trace_id という概念を理解していないからです。

SQLCommenter は、SQL 文にコメントを付加することでこの問題を解決するオープンソースライブラリです。これらのコメントには、コントローラー名、ルート、OpenTelemetry のトレースコンテキストなどのメタデータが含まれます。例えば、標準的なクエリは以下のようになります。

SELECT * FROM users WHERE id = 10;

SQLCommenter を使用すると、次のように変換されます。

SELECT * FROM users WHERE id = 10 /* traceparent='00-84b54...-01', action='get_user', service='identity-provider' */;

データベースエンジンは実行中にこれらのコメントを無視しますが、PostgreSQL の log_statement などのログには記録されます。これにより、ログファイルからスロークエリを見つけ出し、ダッシュボード上で対応するトレースを即座に特定できるようになります。

ツールキットのセットアップ

この例では、Python スタック（SQLAlchemy と FastAPI）を使用します。これは、N+1 クエリ問題やパフォーマンスのボトルネックが潜みやすい一般的な環境です。OpenTelemetry SDK と、使用している ORM 用の SQLCommenter 統合パッケージが必要になります。

1. OpenTelemetry の依存関係をインストールする

まず、コアとなる OTel パッケージと、Web フレームワークおよびデータベースドライバ用の計装（インストルメンテーション）パッケージをインストールします。

bash
pip install opentelemetry-api \
            opentelemetry-sdk \
            opentelemetry-instrumentation-fastapi \
            opentelemetry-instrumentation-sqlalchemy \
            opentelemetry-exporter-otlp

2. SQLCommenter をインストールする

Google は様々な言語向けに SQLCommenter プラグインを提供しています。Python と SQLAlchemy の場合は、以下を実行します。

bash
pip install google-cloud-sqlcommenter

統合の構成

SQLAlchemy エンジンが SQLCommenter の実行ラッパーを使用するように設定することで、統合が完了します。これにより、ORM によって生成されるすべてのクエリに、必要なトレースメタデータが付与されるようになります。

トレーサーの初期化

私は OTel の設定をヘルパー関数にまとめるのが好みです。これにより、アプリケーションがトラフィックの処理を開始する前にトレーサーがアクティブであることを保証できます。

python
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter

def setup_otel(service_name):
    # トレーサープロバイダーの設定
    provider = TracerProvider()
    # OTLPエクスポーターの設定（例：localhost:4317）
    processor = BatchSpanProcessor(OTLPSpanExporter(endpoint="http://localhost:4317"))
    provider.add_span_processor(processor)
    trace.set_tracer_provider(provider)

setup_otel("order-service")

SQLAlchemy の計装

次に、SQLAlchemy に対してクエリにコメントを付加するように指示します。SQLCommenter プラグインを使用するのが最もクリーンな方法です。これにより、コードベース内のすべてのクエリを手動で修正する必要がなくなります。

python
from sqlalchemy import create_engine
from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor
from google.cloud.sqlcommenter.sqlalchemy.executor import BeforeExecuteFactory

DATABASE_URL = "postgresql://user:password@localhost/dbname"
engine = create_engine(DATABASE_URL)

# 標準的な OTel の計装
SQLAlchemyInstrumentor().instrument(engine=engine)

# イベントリスナーを介して SQLCommenter のメタデータを付与
from sqlalchemy import event

@event.listens_for(engine, "before_cursor_execute", retval=True)
def add_sql_comment(conn, cursor, statement, parameters, context, executemany):
    # SQLCommenter のロジックがステートメントに /* key='value' */ を付加する
    # 実際のアプリケーションでは、よりクリーンなコードのためにライブラリ内蔵のファクトリを使用してください
    return statement, parameters

これらのライブラリの最新バージョンでは、ミドルウェアを使用してルート名を自動的に取得できることが多いです。FastAPI の場合、これによりすべての SQL クエリが、どの API エンドポイントによってトリガーされたかを正確に把握できるようになります。

検証：連携の確認

これをデプロイしたら、データが「トレーシングバックエンド（Jaeger や Honeycomb など）」と「データベースログ」の2つのストリームに流れていることを確認します。

1. データベースログの確認

PostgreSQL または MySQL の設定を確認し、クエリログが有効であることを確認してください。PostgreSQL では、log_min_duration_statement = 0 に設定するとすべてのクエリがログに記録されるため、初期テストに役立ちます。

bash
# Postgres のログをリアルタイムで監視
tail -f /var/log/postgresql/postgresql-15-main.log

次のようなエントリが表示されるはずです。

LOG:  duration: 15.210 ms  statement: SELECT * FROM orders WHERE status = 'pending' 
/* action='list_orders', traceparent='00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' */

2. Jaeger での関連付け

ログでスロークエリを見つけたら、traceparent ID をコピーします。その ID を Jaeger の検索バーに貼り付けてください。すると、その特定のリクエストの全ライフサイクルが即座に表示されます。どのユーザーがエンドポイントにアクセスしたか、どのサービスがデータベースを呼び出したか、そしてその SQL 実行に正確に何ミリ秒かかったかを確認できます。

これは特に「N+1」問題の特定に効果的です。Jaeger で100個の小さなクエリが表示されている場合、データベースログの SQL コメントを確認すれば、それらすべてがコード内の同じループから発生したものであることを確信できます。

本番環境での考慮事項

このセットアップは強力ですが、パフォーマンスやストレージのオーバーヘッドを避けるために、慎重に導入する必要があります。

  • ログのボリューム： すべてのクエリにコメントを追加すると、ログのサイズが増加します。トラフィックの多いアプリでは、100ms を超えるクエリなど、特定のしきい値を超えたクエリのみをログに記録することを検討してください。
  • セキュリティ： SQL コメントには絶対に PII（個人を特定できる情報）を含めないでください。ID、ルート名、トレースコンテキストのみに留めます。
  • サンプリング： OpenTelemetry のサンプリング機能を使用してください。意味のあるパターンを見つけるために、すべてのリクエストをトレースする必要はありません。5% のサンプリングレートでも、最大のボトルネックを特定するには十分な場合が多いです。

きめ細かなオブザーバビリティにより、データベースチューニングから推測を排除できます。「データベースが遅い気がする」という漠然とした感覚の代わりに、遅延の原因となっている正確なコード行を特定できるようになります。これにより、DevOps と開発者の関係が、責任のなすりつけ合いから実際の問題解決へとシフトします。

Share:
Tags: