こんにちはSREチームの宮後(@miya10kei)です。最近、スマートホーム化にハマっていていろいろと買い漁っています🛒
N+1問題を検知するのって結構大変ですよね？
今回はDatadogを使ってN+1問題を可視化し、パフォーマンス改善につなげた話を紹介したいと思います。
※ 2024/05/29に開催されたJapan Datadog User Group Meetup#4 でもLTしてきました🎤
N+1問題とは？
N+1問題は主にデータベースへのクエリーを扱う際に出くわすパフォーマンス上の問題です。1つのクエリーでN件のデータを取得した後にそれぞれのデータに対して追加でクエリーが発行されることでパフォーマンスを大幅に低下させます。（1 + N問題と呼んだ方がしっくりくる気がしますが...🤫）
背景
この取り組みを始めた経緯は、システムへのリクエスト数に対してデータベースの負荷が高いことに気付いたことからです。Datadogを導入してAPMを有効化していたため、データベースに対する全体のSQL発行数が異常に多いことはすぐに特定できました。また、N + 1問題が発生している可能性も容易に予測できました。しかし、具体的にどのAPIで問題が発生しているのかを特定するのが難しかったため、まずは計測してみることにしました。
メトリクスの計測
アプリケーション上でAPI毎のSQLの発行数を計測し、Datadogに転送し可視化することで対象のAPIを特定することにしました。
全体構成
Park DirectのアプリケーションはAWS ECS(Fargate)上で稼働しており、もともとdatadog-agentがサイドカーとして存在していました。
アプリケーション側でOpenTelemetryで計測し、datadog-agent経由でDatadogにメトリクスを蓄積する構成としました。DatadogのSDKの利用も検討しましたが、今後LogsなどもOpenTelemetryの仕様に準拠していきたいという思いもあったので採用しませんでした。
アプリケーション側の実装
Park DirectのアプリケーションはPython x Djangoという技術スタックとなっています。
他言語の主要なフレームワークであれば似た機能が存在していると思うので参考にしてみてください。
アプリケーション実装の全体構成を載せ、詳細を紹介していきます。
計測するメトリクス
アプリケーション側では次の2つのメトリクスを計測しています。
この２つのメトリクスから次の計算式でAPI毎の平均SQL発行数を算出します。
APIの平均SQL発行数 = database.sql.issued_count / http.server.requests
| メトリクス名 | 属性 | 説明 |
|---|---|---|
| http.server.requests | http.method, http.path | API毎のリクエスト数を記録するメトリクス |
| database.sql.issued_count | http.method, http.path | API毎のSQL発行数を記録するメトリクス |
上記メトリクスの計測にはOpenTelemetry SDKを利用しています。SDKの使い方は公式サイトに譲るとして、特徴的な部分を2点紹介します。
1点目はインスタンスをシングルトンにしている点です。シングルトンにすることでOpenTelemeryのメトリクスが複数できるのを防いでいます。
2点目はメトリクス毎に関数を定義している点です。関数化することでメトリクスの属性名がゆれることを防いでいます。以下は実際のコードです。
import os from django.conf import settings from opentelemetry import metrics as otel_metrics from opentelemetry.exporter.otlp.proto.http.metric_exporter import OTLPMetricExporter from opentelemetry.sdk.metrics import MeterProvider from opentelemetry.sdk.metrics.export import PeriodicExportingMetricReader from opentelemetry.sdk.resources import ( HOST_NAME, PROCESS_PID, Resource, SERVICE_NAME, ) class Metrics(object): __instance = None def __new__(cls): if cls.__instance is None: cls.__instance = super(Metrics, cls).__new__(cls) return cls.__instance def __init__(self): if not hasattr(self, '__initialized'): setattr(self, "initialized", True) self.__initialize_opentelemetry() self.__initialize_metrics() def __initialize_opentelemetry(self): resource = Resource( attributes={ HOST_NAME: str(os.getenv('HOSTNAME')), SERVICE_NAME: settings.APPLICATION_NAME, # preforkモデルで稼働しているためPIDを属性に付与しています PROCESS_PID: os.getpid(), } ) reader = [PeriodicExportingMetricReader(OTLPMetricExporter())] provider = MeterProvider(resource=resource, metric_readers=reader) otel_metrics.set_meter_provider(provider) def __initialize_metrics(self): meter = otel_metrics.get_meter('opentelemetry.instrumentation.xxxx') self.http_server_requests = meter.create_counter( 'http.server.requests', description='The number of requests', ) self.database_sql_issued_counts = meter.create_counter( 'database.sql.issued_counts', description='The number of SQL issued', ) def increment_http_server_requests(self, method: str, path: str, status: int): self.http_server_requests.add(1, {'http.method': method, 'http.path': path, 'http.status': status}) def increment_database_sql_issued_counts(self, method: str, path: str): self.database_sql_issued_counts.add(1, {'http.method': method, 'http.path': path}) metrics = Metrics()
リクエスト数（http.server.requests）の計測
DjangoにはMiddlewareと呼ばれるAPI処理の前後で任意の処理にフックさせる機能が存在します。こちらを利用しAPIのリクエスト数を計測しています。また、後続処理の中でリクエストの情報（http.method、http.path）を参照したいのでThreadLocal領域に保存することで同スレッド内から参照できるようにしています。以下は実際のコードです。
import threading from django.urls import resolve from apps.core.opentelemetry import metrics REQUEST_CONTEXT = threading.local() HTTP_METHOD_KEY = 'http_method_key' HTTP_PATH_KEY = 'http_path_key' class RequestContextMiddleware: def __init__(self, get_response): self.get_response = get_response def __call__(self, request): self.__pre_process(request) response = self.get_response(request) self.__post_process(response) return response def __pre_process(self, request): try: method = request.method if request.method else 'unknown' resolved_path = resolve(request.path).route setattr(REQUEST_CONTEXT, HTTP_METHOD_KEY, method) setattr(REQUEST_CONTEXT, HTTP_PATH_KEY, resolved_path) except Exception: setattr(REQUEST_CONTEXT, HTTP_METHOD_KEY, 'unknown') setattr(REQUEST_CONTEXT, HTTP_PATH_KEY, 'unknown') def __post_process(self, response): try: method = get_context_str_value(HTTP_METHOD_KEY, 'unknown') path = get_context_str_value(HTTP_PATH_KEY, 'unknown') status = response.status_code metrics.increment_http_server_requests(method, path, status) delattr(REQUEST_CONTEXT, HTTP_METHOD_KEY) delattr(REQUEST_CONTEXT, HTTP_PATH_KEY) except Exception: pass def get_context_str_value(key: str, default=None) -> str: return str(getattr(REQUEST_CONTEXT, key, default))
SQL発行数（database.sql.issued_count）の計測
こちらは少しトリッキーな方法になっています。
SQL発行の前後で処理をフックさせメトリクスの計測をおこないたかったのですが、Djangoには適切な機能がありませんでした（探したけど見つからなかった...）
他の言語であれば例えばJavaのMySQLのJDBC DriverにあたるConnector/JなどはInterceptorという機能が存在しSQLの実行前後で処理をフックさせることができます。
そこで今回はDabaseEngine部分を拡張することで実現しました。
もともと使用していたPostGISのDatabaseEngineをラップし、SQLの発行を担うメソッドをオーバーライドすることで計測しています。以下は実際のコードです。
from django.conf import settings from django.contrib.gis.db.backends.postgis import base from psycopg2.extensions import cursor from apps.core.middleware.request_context import ( HTTP_METHOD_KEY, HTTP_PATH_KEY, get_context_str_value, ) from apps.core.opentelemetry import metrics class DatabaseWrapper(base.DatabaseWrapper): def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) def create_cursor(self, name=None): if name: cursor = self.connection.cursor( name, cursor_factory=CustomeCursor, scrollable=False, withhold=self.connection.autocommit ) else: cursor = self.connection.cursor(cursor_factory=CustomeCursor) cursor.tzinfo_factory = self.tzinfo_factory if settings.USE_TZ else None return cursor class CustomeCursor(cursor): def execute(self, sql, params=None): super().execute(sql, params) method = get_context_str_value(HTTP_METHOD_KEY, 'unknown') path = get_context_str_value(HTTP_PATH_KEY, 'unknown') metrics.increment_database_sql_issued_counts(method, path) def executemany(self, sql, param_list): super().executemany(sql, param_list) method = get_context_str_value(HTTP_METHOD_KEY, 'unknown') path = get_context_str_value(HTTP_PATH_KEY, 'unknown') metrics.increment_database_sql_issued_counts(method, path)
OpenTelemtry -> datadog-agent間のメトリクス転送設定
続いてアプリケーションで計測したメトリクスをdatadot-agentに転送するための設定を紹介します。
datadog-agentコンテナの設定
datadog-agnetはOpenTelemetryをサポートしているので環境変数を設定するだけでリクエストを受け付けることができます。
| 環境変数 | 値 | 説明 |
|---|---|---|
| DD_OTLP_CONFIG_RECEIVER_PROTOCOLS_HTTP_ENDPOINT | 0.0.0.0:4318 | OpenTelemeryからのメトリクス転送を受け付けるエンドポイント |
| DD_OTLP_CONFIG_METRICS_RESOURCE_ATTRIBUTES_AS_TAGS | true | ECSのリソース情報をメトリクスの属性に追加する設定 |
Park Directではdatadog-agentはサイドカーとして動作しているので、アプリケーションからの通信を許可するために以下のようにPortMappingを設定します。
| hostPort | containerPort | protocol |
|---|---|---|
| 4318 | 4318 | tcp |
アプリケーションコンテナの設定
OpenTelemetryのExporterは環境変数でメトリクスの転送先を指定することができます。以下のように設定することでdatadog-agentのサイドカーに転送することができます。
| 環境変数 | 値 | 説明 |
|---|---|---|
| OTEL_EXPORTER_OTLP_ENDPOINT | http://localhost:4318 | OpenTelemetry Exporterのメトリクス転送先 |
計測結果を可視化
前述の方法で計測したメトリクスを元にAPI毎の平均SQL発行数をランキング化してみると1回のリクエストで数百回SQLを発行しているAPIを特定することができました！（すこし多いですね...😅）
あとは個別にAPMのTrace情報を確認することで実際にN+1問題が発生していることを確認できたので個別に改善を進めていきました！
改善効果
個別に改善を進めていったことでリクエストあたりの平均SQL発行数を50%程削減することができました。
また、システム全体のAPIレイテンシーについても90パーセンタイル値で約200ms程改善されパフォーマンスを大きく改善することができました🎉
注意点
紹介した方法で計測したメトリクスは、Datadog上ではカスタムメトリクスとして扱われます。カスタムメトリクスは同じメトリクスでも属性値が異なる場合は別ものとしてカウントされます。そのため、リクエスト毎に異なる値を属性値に設定してしまうと気づいたら多額の請求が発生しているということにもなりかねないので十分に気を付けてご利用ください。公式サイトでカスタムメトリクスの課金形態が説明されているので利用の際は必ずお読みください。
今後やりたいこと
今回、API毎のSQL発行数を可視化しN+1を改善することでパフォーマンスを大きく向上させることができました！
ですが、まだいくつかやりたいことも残っているので最後に紹介して終わりたいと思います。
１つ目はコスト削減です。Park Directのアプリケーションはpreforkモデルで動作しており、属性値にPIDを埋め込んでいるため余計なコストが発生しています。datadog-agentに転送する前に各プロセスのメトリクスを集約することでコストを削減していきたいと考えています。
２つ目は継続的な監視です。SQLの発行数はAPI毎に大きく異なっているため従来の閾値を設定した監視では難しいと考えています。（API数も多く個別の監視設定を運用するのもコストが高いです）一方で同じAPIであれば1リクエスト中のSQL発行数はそれほど大きな差は発生していません。このようなケースではDatadogの異常検知モニターが効果を発揮するのではないかと考えているので今後導入を検討していきます。
それでは、N+1を撲滅して安定したシステム稼働を目指しましょう！！！
