株式会社ブレインパッド プロダクトユニットの岡です。
弊社は「データ活用の促進を通じて持続可能な未来をつくる」をミッションに、
データ分析支援やSaaSプロダクトの提供を通じて、企業の「データ活用の日常化」を推進しております。
私は、SaaSプロダクトを開発・提供する「プロダクト・サービス」部門に所属し、
企業のマーケティング活動をデータで支援する「Rtoaster GenAI」の開発を担当しております。
はじめに
Rtoaster GenAI は、生成 AI を活用したサイト内検索・レコメンドサービスです。ユーザーが入力した検索キーワードを LLM が解釈し、ベクトル検索でアイテムを取得してキャプションや推奨理由を自動生成して返すことで、EC サイトの CVR 向上や回遊率改善を支援しています。同一クエリへの応答を高速化するキャッシュ機能も備えており、繰り返しアクセスされる人気キーワードでは LLM 呼び出しをスキップして即時返却します。
機能リリースが一段落したタイミングで、次のスケール要件に備えてパフォーマンスの余力を計測・改善するプロジェクトに取り組みました。本記事では、プロファイリングによってボトルネックを特定し、改善した過程を紹介します。
技術スタックは以下のとおりです。
- フレームワーク: FastAPI（Python）
- DB クライアント: asyncpg（PostgreSQL）
- アーキテクチャ: Onion Architecture
- 実行環境: Cloud Run
パフォーマンス計測：高負荷時のレイテンシ傾向を把握する
まず現状把握として、キャッシュ機能を ON にした状態でクエリを固定し、さまざまな RPS で負荷試験を実施しました。
| 負荷レベル | レイテンシ傾向 |
|---|---|
| 高（上限付近） | レイテンシが大幅に増大し、エラーが発生し始める |
| 中高 | 継続するとレイテンシが悪化してくる |
| 中 | リクエストは通るが p(95) が目標値を超える |
| 低 | 概ね許容範囲 |
インスタンスはリクエスト量に応じてスケールするものの、高負荷下ではリクエストの処理待ちが積み上がる傾向が見られました。高負荷時のレイテンシに改善余地があると判断し、プロファイリングに進みました。
pyinstrument でプロファイリングする
遅いという事実はわかりましたが、どこが遅いのかを特定するためにプロファイリングを実施しました。使用したライブラリは pyinstrument です。
コールスタックを木構造で表示し、各ノードに消費時間と割合が付きます。どのパスがボトルネックかが視覚的にわかります。
FastAPI への組み込み方
開発環境でのみ有効にするミドルウェアとして組み込みます。クエリパラメータ ?profile=true を付けてリクエストすると、レスポンスとしてプロファイル結果の JSON が返ってくる仕組みです。
ただし、プロファイル結果生成そのものの処理影響をなるべく低くするため、リクエストの1%未満で確率的に生成するなどの工夫をしました。
以下は実装イメージです。
from pyinstrument import Profiler
@app.middleware("http")
async def profile_middleware(request: Request, call_next):
if request.query_params.get("profile"):
profiler = Profiler(async_mode="enabled")
with profiler:
response = await call_next(request)
return JSONResponse(profiler.output(renderer="json"))
return await call_next(request)
複数サンプルを取って傾向を掴む
1 リクエストのプロファイルだけだとノイズが混じるため、数リクエスト分を手動で収集して傾向を確認しました。pyinstrument の JSON 出力はスクリプトで集計・比較しやすく、複数サンプルを横断して「このコールスタックが毎回重い」という傾向を定量的に掴めます。
pyinstrument 出力のイメージ（抜粋）：
3.820 handle_request main.py
└── 3.801 generate_json main.py
└── 3.799 generate_content application/generate.py
├── 1.692 unit_of_work ... ← ここに時間が集中
│ └── 1.689 model_validate pydantic/...
│ └── 1.687 is_timezone models/site.py:18
│ └── 1.685 available_timezones zoneinfo/...
├── 0.921 generate_text services/llm.py ← LLM 呼び出し
└── 0.624 release asyncpg/pool.py ← DB 接続解放
LLM の呼び出しは本質的に時間がかかるため無視できますが、available_timezones() が想定外に重いことがこの出力から読み取れます。
また、speedscope などのツールを用いて視覚的に確認することで、処理の概要をよりわかりやすく理解することができます。
以下は speedscope のイメージ図です。
ボトルネック 1：Pydantic のバリデーション
pydantic_extra_types の TimezoneName バリデーターは内部で zoneinfo.available_timezones() を呼ぶそうです。この関数は毎回ファイルシステムをスキャンしてタイムゾーン一覧を構築するため、数十ms 程度の処理時間があります。
問題は呼ばれる頻度で、DB から fetch するたびに pydantic のバリデーションが走るため、1 リクエストで複数回呼ばれます。
後にも書きましたが、すでに取得済みの値をDBから再度取得している問題も相まって、余計に遅くなっていました。
ボトルネック 2：サイト情報の二重取得
CORS 検証などをミドルウェアで行っています。
検証の際、ミドルウェアですでに取得済みの情報を捨てて再取得していたため、余計なDBアクセスが発生してました。
ボトルネック3：ログ保存処理と Google Cloud DLP
ログ保存の概要
この API では、1 リクエストごとに検索クエリや LLM 出力などを含むふくむを検索ログをストレージに保存しています。ただし検索クエリにはユーザーが入力した自由テキストが含まれるため、保存前に Google Cloud DLP API を使って PII（個人情報）をマスキングする処理を挟んでいます。
リクエスト処理 → レスポンス返却
↓ (BackgroundTasks として非同期実行)
DLP API でクエリ・LLM 出力の PII をマスキング
↓
マスキング済みログをストレージに保存
マスキング対象のフィールドは、検索クエリ・LLM へのプロンプト・LLM が生成したキャプションや推奨理由など複数にわたります。これらを 1 回の DLP API 呼び出しにまとめてバッチ処理することでリクエスト数を削減しています。
background_tasks のブロッキング
BackgroundTasks はレスポンスを返した後に非同期で実行されるため、リクエスト処理のレイテンシには影響しないはずです。しかし 1 リクエストのプロファイルを詳しく見ると、DLP の処理がレスポンス返却をある程度ブロックしているような挙動が観測されました。
直接的な原因は、バックグラウンドタスク内の DLP API 呼び出しに await が抜けていたことです。await なしでコルーチンを呼び出すとイベントループ上で実行されず、結果として同期的にブロッキングする挙動になります。await を追加することで正しく非同期実行されるようになり、ブロッキングが解消されました。
改善結果
問題 1・2・3 の対応後に再度負荷試験を実施した結果です。
| 指標 | 改善前 | 問題 1〜3 対応後 |
|---|---|---|
| p(95) | 基準値 | 約 1/4 に短縮 |
| avg | 基準値 | 約 1/4 に短縮 |
| med | 基準値 | 約 1/6 に短縮 |
| 高負荷時の成功率 | 改善余地あり | 目標クリア |
目標としていた p(95) の閾値を大幅に下回る結果となりました。改善前と比較すると p(95) で数倍の高速化です。
まとめ
- コードを読んで推測するのではなく、測定することでボトルネックを改善することができました
- Pydanticのバリデータが内部でファイルシステムにアクセスしているケースのように、意図しない重い処理がループや高頻度なデータ変換に潜んでいることがある
- FastAPIの
BackgroundTasksは便利ですが、内部の実装でawaitを忘れるとイベントループをブロッキングし、API全体のレイテンシ悪化に直結する
同様のスタックで性能課題を抱えている方の参考になれば幸いです。