はじめに
現在、仕事でFastAPI+SQLAlchemyがバックエンドのWebアプリケーションを開発しています。
先日、数十リクエストが同時に飛ぶページを開発したところ、アプリ全体が数十秒フリーズし、タイムアウトが多発するという現象に遭遇しました。
調査の結果、以下の複合的な要因でFastAPIのメインスレッドのイベントループがブロックされ、デッドロックのような状態に陥っていたことが判明しました。
- FastAPIの
async defエンドポイントを使用 - 内部で 同期版 SQLAlchemyを使用
- コネクションプールの上限に到達
PythonのイベントループやFastAPIのエンドポイントの挙動、そしてSQLAlchemyのコネクションプールの仕様について理解を深めるきっかけになったので、アドベントカレンダーの時期のタイミングで自戒を込めて記事にします。
伝えたいこと
SQLAlchemy(同期モード)などのブロッキングI/Oを含む処理を行う場合、FastAPIのエンドポイントは async def ではなく def で定義すべきである。
開発中のアプリケーションではasyncの処理が必要なライブラリとSQL Alchemy(同期)を併用しており、エンドポイントをasync defで定義していましたが、安易にasync をつけると、アプリケーション全体のパフォーマンスを殺してしまう可能性があります。
起きた現象
-
複数のAPIエンドポイントを同時にリクエストした際、サーバー全体が応答しなくなりました。
-
ログを調査すると、下記のエラーが発生していました。
sqlalchemy.exc.TimeoutError: QueuePool limit of size 20 overflow 0 reached, connection timed out, timeout 30.00 (Background on this error at: https://sqlalche.me/e/20/3o7r) -
一見すると単なるDB負荷によるタイムアウトに見えますが、クエリ自体は数ミリ秒で終わるはずの軽い処理だったので、30秒も待たされるのかが不可解でした。
調査した内容
1. SQL Alchemyの仕様の確認
まず、エラーログからSQLAlchemyの Connection Pool が枯渇していることがわかりました。
-
Connection Pool: DB接続コスト(ハンドシェイク、認証など)削減のため、接続を保持・再利用する仕組み。 -
Session: トランザクションの単位。クエリ実行時にPoolからConnectionを「借り(Checkout)」、close()時に「返す(Checkin)」。
すべてのConnectionが貸し出された状態で、次のリクエストがConnectionを要求したため待機が発生していたようです。
参考文献:公式Doc
2. エラーの再現
原因を切り分けるため、SQLAlchemyの設定を「同時に1つしか接続できない」状態に極端に絞り、ログ詳細を出力するようにしました。
# 再現用の極端な設定
engine = create_engine(
url,
pool_size=1, # Pool内のConnection数: 1
max_overflow=0, # overflowを許可しない
pool_timeout=10 # 10秒借りられなかったらTimeoutError
)
この状態で、軽いクエリを実行するエンドポイントを 2つ同時に 叩いてみました。
予想では「1つ目は即座に完了し、2つ目は少し待ってから完了する」はずですが、結果は 「両方とも10秒間フリーズし、1つは成功(200)、もう1つはタイムアウト(500)」 となりました。
1つ目の処理が軽いはずなのに、道連れのようにフリーズするのが謎でした。
3. FastAPIの仕様の確認
ここでFastAPIのドキュメント(Technical Details)を見直しました。
-
async def: Pythonの メインスレッド(イベントループ) 上で実行されます。ここでブロッキング処理(重い計算や同期I/O)を行うと、イベントループ全体が停止します。 -
def: 外部の スレッドプール(別スレッド) で実行されます。ここでブロッキング処理を行っても、メインスレッドは止まりません。
この仕様についてはこちらの記事がとてもわかりやすかったです。
4. エンドポイントの実装の確認
エンドポイントの実装を確認したところ、該当の処理が見事に上記のアンチパターンを踏んでいました…
さらに、Dependsを使ってSession管理(Connectionの取得と返却)を行っていたため、エンドポイントの処理が完了してレスポンスを返すまでConnectionが返却されない構造になっていました。
# 実装例
from sqlalchemy.orm import Session
def get_session():
session = SessionLocal()
try:
yield session
finally:
session.close()
@app.get("/users")
async def get_users(session: Session = Depends(get_session)):
return session.query(User).all()
5. わかったこと
上記の調査内容を踏まえて、起きていた現象の詳細が判明しました。
- リクエストA 到着:Poolから唯一のConnectionを取得し、処理開始。
- リクエストB 到着:PoolからConnectionを取得しようとするが、空きがないため 待機(Wait) に入る。
- リクエストBは async def 内にいるため、この「SQLAlchemyの同期待機」が メインスレッドのイベントループを完全にブロックする。
- イベントループが止まったため、リクエストAの処理(レスポンス返却&Connection返却)も停止する。
- リクエストAはConnectionを返したいのに動けず、リクエストBはConnectionが空くのを待ち続ける(デッドロック状態)。
- 10秒経過し、リクエストBがタイムアウトエラーで脱落。
- イベントループが動き出し、リクエストAがようやく完了。
実際のログ(クリックで展開)
[POOL] Connection checked out
[SQL] START: SELECT (略) FROM (略)
[SQL] END (0.008 sec)
Exception: TimeoutError
[POOL] Connection checked in (held 10.050 sec)
[POOL] Connection checked out
[SQL] START: SELECT (略) FROM (略)
[SQL] END (0.019 sec)
[SQL] START: SELECT (略) FROM (略)
[SQL] END (0.034 sec)
INFO: - "GET {リクエストB} HTTP/1.1" 500 Internal Server Error
INFO: - "GET {リクエストA} HTTP/1.1" 200 OK
[POOL] Connection checked in (held 0.091 sec)
検証に使用したログ出力コード(クリックで展開)
# --- 接続の checkout / checkin をトレース ---
@event.listens_for(engine, "checkout")
def checkout(dbapi_conn, conn_record, conn_proxy):
conn_record.info["t_checkout"] = monotonic()
logger.info("[POOL] Connection checked out")
@event.listens_for(engine, "checkin")
def checkin(dbapi_conn, conn_record):
t0 = conn_record.info.pop("t_checkout", None)
if t0:
held = monotonic() - t0
logger.info(f"[POOL] Connection checked in (held {held:.3f} sec)")
# --- クエリの before / after execute をトレース ---
@event.listens_for(engine, "before_cursor_execute")
def before_cursor_execute(conn, cursor, statement, parameters, context, executemany):
conn.info.setdefault("query_start_time", []).append(monotonic())
logger.info(f"[SQL] START: {statement}")
@event.listens_for(engine, "after_cursor_execute")
def after_cursor_execute(conn, cursor, statement, parameters, context, executemany):
start_time = conn.info["query_start_time"].pop(-1)
total = monotonic() - start_time
logger.info(f"[SQL] END ({total:.3f} sec)")
解決策
1. エンドポイントを def に変更する
同期ライブラリを使っているエンドポイントの定義を async def から defにすることにより、DB接続待ちが発生しても、その待機は「FastAPIのスレッドプール内のいちスレッド」で発生するだけになります。
メインスレッドのイベントループは健全に動き続けるため、上記の例でリクエストAの処理は滞りなく完了し、Connectionが返却され、待機していたリクエストBも処理を再開できるようになります。
実際、この修正だけでエラー再現設定(Pool=1)でも詰まることなく動作するようになりました。
2. その他のアプローチ
- 非同期ドライバを使用する
- asyncpg や aiosqlite などを使い、SQLAlchemyを非同期モード(AsyncSession)で動作させる場合は、async def のままで問題ない
- むしろasyncで実行する方がスレッドの切り替えのオーバヘッドがない分いいかもしれない
- Connectionの早期返却
- 依存注入(Depends)に頼らず、コンテキストマネージャ等を使って必要な区間だけConnectionを保持するようにすれば、LLM呼び出し等の長い処理中にConnectionを握り続けるのを防ぐことができる
まとめ
- FastAPIだからといって、思考停止で
async defを使うのは危険です。 - 内部で使っているライブラリが「同期」なのか「非同期」なのかを意識しましょう。
- 同期ORMなど、ブロッキングな処理を行う場合は、素直に
defでエンドポイントを定義することで、FastAPIが良きに計らって(スレッドプールで実行して)くれます。
発端は開発中の予期せぬ挙動でしたが、あやふやにしていた仕様を詰めていく作業はとても楽しかったです!
また、ドキュメントはちゃんと読もう、という基本に立ち返る良い機会でもありました。
またこういう記事を書こうと思います。