SQLAlchemyでSQLクエリをログに表示する方法

背景

SQLAlchemyを使用する際に、SQLクエリをログに表示したい

現状のログ

2024-06-05 10:47:42.877 | INFO     | backend.interface.api.healthz:healthz:19 - Database connection successful
2024-06-05 10:47:42.878 | INFO     | uvicorn.protocols.http.httptools_impl:send:481 - 127.0.0.1:53438 - "GET /healthz HTTP/1.1" 200

対象のコード

@router.get("/healthz")
async def healthz(session: AsyncSession = Depends(get_session)) -> JSONResponse:
    try:
        async with session.begin():
            # データベース接続確認クエリ
            result = await session.execute(text("SELECT 1"))
            _ = result.fetchone()
        logger.info("Database connection successful")
        return JSONResponse(
            status_code=200, content={"status": "ok", "database": "connected"}
        )
    except Exception as e:
        logger.exception(f"Health check failed: {str(e)}")
        return JSONResponse(
            status_code=500,
            content={"status": "error", "database": "disconnected", "error": str(e)},
        )

やったこと

SQLAlchemyのエンジン作成時に、echoオプションを有効にするだけで、SQLクエリのログ出力が可能

Engine = create_async_engine(DATABASE_URL)

↓

Engine = create_async_engine(DATABASE_URL, echo=True)

動作確認

echo=Trueオプションを有効にしたことで、以下のようにSQLクエリがログに表示された

2024-06-05 10:53:26,686 INFO sqlalchemy.engine.Engine SELECT DATABASE()
2024-06-05 10:53:26,686 INFO sqlalchemy.engine.Engine [raw sql] ()
2024-06-05 10:53:26,688 INFO sqlalchemy.engine.Engine SELECT @@sql_mode
2024-06-05 10:53:26,688 INFO sqlalchemy.engine.Engine [raw sql] ()
2024-06-05 10:53:26,688 INFO sqlalchemy.engine.Engine SELECT @@lower_case_table_names
2024-06-05 10:53:26,688 INFO sqlalchemy.engine.Engine [raw sql] ()
2024-06-05 10:53:26,689 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2024-06-05 10:53:26,690 INFO sqlalchemy.engine.Engine SELECT 1
2024-06-05 10:53:26,690 INFO sqlalchemy.engine.Engine [generated in 0.00021s] ()
2024-06-05 10:53:26,691 INFO sqlalchemy.engine.Engine COMMIT
2024-06-05 10:53:26.691 | INFO     | backend.interface.api.healthz:healthz:19 - Database connection successful
2024-06-05 10:53:26.692 | INFO     | uvicorn.protocols.http.httptools_impl:send:481 - 127.0.0.1:53455 - "GET /healthz HTTP/1.1" 200

まとめ

SQLAlchemyでSQLクエリをログに表示する方法は非常に簡単だった。create_async_engine関数にecho=Trueオプションを追加するだけ。
これでデータベースとのやり取りを詳細に把握できるため、アプリケーションのパフォーマンス向上や問題解決が容易になる。