I’m experiencing an issue with my FastAPI backend where I use SQLAlchemy for database connection pooling. Frequently, I encounter a 16-minute delay when hitting an API endpoint, especially under concurrent requests. It seems that requests sometimes hang for exactly 16 minutes before responding. This delay occurs whether I use create_engine or create_async_engine for the connection pool.
Here’s my connection pool configuration and the relevant code:
engine = create_async_engine(
URL,
echo_pool=True,
echo=False,
poolclass=AsyncAdaptedQueuePool,
pool_pre_ping=True,
pool_size=64,
max_overflow=64,
pool_timeout=3,
pool_recycle=3600
)
SessionLocal = sessionmaker(
autocommit=False,
autoflush=False,
class_=AsyncSession,
bind=engine,
expire_on_commit=False,
)
async def get_db_session() -> AsyncSession:
async with SessionLocal() as session:
logger.debug(
f"pid:{os.getpid()} | {session.get_bind().pool.status()} | {session.is_active} {session._is_asyncio}")
yield session
I’m trying to understand whether this 16-minute delay is caused by SQLAlchemy or if it’s happening at another step, as it significantly affects the application’s performance.
more details:
SessionLocal = sessionmaker(
autocommit=False,
autoflush=False,
class_=AsyncSession,
bind=engine,
expire_on_commit=False,
)
async def get_db_session() -> AsyncSession:
async with SessionLocal() as session:
logger.debug(
f"pid:{os.getpid()} | {session.get_bind().pool.status()} | {session.is_active} {session._is_asyncio}")
yield session
SessionDep = Annotated[AsyncSession, Depends(get_db_session)]
@router.get("", response_model=ResponseData)
@exception_handler
async def read_chat(session: SessionDep, current_user: CurrentUser, customer_id: int = None, page: int = 0, page_size: int = 10) -> Any:
"""
Retrieve chats
"""
chats = await crud_chat.get_user_chats(user_id=current_user.id, db_session=session, page=page-1, page_size=page_size)
router_ids = list(set([chat.router_id for chat in chats]))
customers = await crud_customer.get_customer_by_router_id(router_ids=router_ids, db_session=session)
router_id_to_name = {customer.router_id: customer.name for customer in customers}
router_id_to_avatar = {customer.router_id: customer.avatar for customer in customers}
total_count = await crud_chat.get_user_chats_count(user_id=current_user.id, db_session=session)
res = []
for chat in chats:
chat = chat.dict()
chat["customer_name"] = router_id_to_name.get(chat["router_id"])
chat["avatar"] = router_id_to_avatar.get(chat["router_id"])
res.append(chat)
return ResponseData(
data={"chats": res,
"count": len(chats),
"total_count": total_count}
)
async def get_user_chats(self, user_id: int, db_session: AsyncSession = None, page: int = 0,
page_size: int = 10):
async with get_db_session() if db_session is None else db_session as session:
chats = await session.execute(
select(Chat).where(Chat.uid == user_id).order_by(desc(Chat.ctime)).offset(page * page_size).limit(
page_size))
return chats.scalars().all()
async def get_customer_by_router_id(self, router_ids: list[int], db_session: AsyncSession = None):
async with get_db_session() if db_session is None else db_session as session:
customers = await session.execute(select(Customer).where(Customer.router_id.in_(router_ids)))
return customers.scalars().all()
async def get_user_chats_count(self, user_id: int, db_session: AsyncSession = None):
async with get_db_session() if db_session is None else db_session as session:
response = await session.execute(
select(func.count()).select_from(Chat).where(Chat.uid == user_id))
return response.scalar_one_or_none()
more log:
INFO: 2024-09-12 09:38:48 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:59262 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/chats?page=1&page_size=10 HTTP/1.1" 200 OK - start:2024-09-12 09:38:48.085971 - duration:0.121s
DEBUG: 2024-09-12 10:10:24 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -63 Current Checked out connections: 0 | True True
DEBUG: 2024-09-12 10:10:27 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 0 Current Overflow: -63 Current Checked out connections: 1 | True True
INFO: 2024-09-12 10:10:27 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:57016 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:10:27.216939 - duration:0.072s
DEBUG: 2024-09-12 10:11:55 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
INFO: 2024-09-12 10:11:55 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:59876 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:11:55.358777 - duration:0.039s
DEBUG: 2024-09-12 10:12:47 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
INFO: 2024-09-12 10:12:47 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:35564 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:12:47.175676 - duration:0.056s
DEBUG: 2024-09-12 10:13:16 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::61 - login_wx_openid api: 0b1RIG000kR9OS1U4w300BqHYp2RIG0d|https://api.weixin.qq.com/sns/jscode2session?appid=wx07a78f2707c84c7c&secret=7232404fad846751730e1c9bba5ecdb7&js_code=0b1RIG000kR9OS1U4w300BqHYp2RIG0d&grant_type=authorization_code
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::63 - login_wx_openid weixin http get start
[12/Sep/2024 10:13:16] INFO - HTTP Request: GET https://api.weixin.qq.com/sns/jscode2session?appid=wx07a78f2707c84c7c&secret=7232404fad846751730e1c9bba5ecdb7&js_code=0b1RIG000kR9OS1U4w300BqHYp2RIG0d&grant_type=authorization_code "HTTP/1.1 200 OK"
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::65 - login_wx_openid weixin http get end: 0b1RIG000kR9OS1U4w300BqHYp2RIG0d|https://api.weixin.qq.com/sns/jscode2session?appid=wx07a78f2707c84c7c&secret=7232404fad846751730e1c9bba5ecdb7&js_code=0b1RIG000kR9OS1U4w300BqHYp2RIG0d&grant_type=authorization_code|<Response [200 OK]>
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::75 - crud.get_user_by_openid start:0b1RIG000kR9OS1U4w300BqHYp2RIG0d|{'session_key': 'AGPAK8UlXBuD08iT7ZWGWQ==', 'openid': 'o1nWj5I8EqZTz9BY70LHThW9z1Yo'}
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::77 - crud.get_user_by_openid end:0b1RIG000kR9OS1U4w300BqHYp2RIG0d|role='normal' is_active=True group_id=1 is_valid=True id=1000000052 openid='o1nWj5I8EqZTz9BY70LHThW9z1Yo' name='llun' avatar='https://www.ai4x.cloud:32494/chatbot-test/avatar/user/object-1726043828974142787.jpg' level_id=1 hashed_password='$2b$12$w16ImxedF2H8szonjHt07ejHXDjwMtxwe0.aI62mkd4kV9ParQJvG'
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::91 - create_access_token start: 0b1RIG000kR9OS1U4w300BqHYp2RIG0d|1000000052
DEBUG: 2024-09-12 10:13:16 - sellingexpert.api.routes.login::login_wx_openid::93 - create_access_token end: 0b1RIG000kR9OS1U4w300BqHYp2RIG0d|1000000052|eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJleHAiOjE3NjIzOTUxOTYsInN1YiI6IjEwMDAwMDAwNTIifQ.bnlfWDxkkM570VNdL674vzz46Iw1cdgfrcHt2sv5z-0
INFO: 2024-09-12 10:13:16 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:45742 - "POST http://www.dev.ai4x.cloud:32494/selling/api/v1/login/wx-openid HTTP/1.1" 200 OK - start:2024-09-12 10:13:16.409646 - duration:0.320s
DEBUG: 2024-09-12 10:13:16 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
INFO: 2024-09-12 10:13:16 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:45742 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/user/refresh_userinfo/ HTTP/1.1" 200 OK - start:2024-09-12 10:13:16.801077 - duration:0.035s
DEBUG: 2024-09-12 10:13:17 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
INFO: 2024-09-12 10:13:17 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:45742 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:13:17.851945 - duration:0.053s
DEBUG: 2024-09-12 10:13:56 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
INFO: 2024-09-12 10:13:56 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:50362 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/chats?page=1&page_size=10 HTTP/1.1" 200 OK - start:2024-09-12 10:13:56.258594 - duration:0.110s
DEBUG: 2024-09-12 10:25:01 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -62 Current Checked out connections: 1 | True True
DEBUG: 2024-09-12 10:25:09 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 0 Current Overflow: -62 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:09 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:54828 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:09.060476 - duration:0.075s
DEBUG: 2024-09-12 10:25:23 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:23 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:23.056793 - duration:0.054s
DEBUG: 2024-09-12 10:25:24 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:24 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:24.471383 - duration:0.055s
DEBUG: 2024-09-12 10:25:25 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:25 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:25.383615 - duration:0.053s
DEBUG: 2024-09-12 10:25:26 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:26 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:26.408128 - duration:0.053s
DEBUG: 2024-09-12 10:25:27 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:27 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:27.185809 - duration:0.053s
DEBUG: 2024-09-12 10:25:31 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:31 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:31.073784 - duration:0.052s
DEBUG: 2024-09-12 10:25:32 - sellingexpert.db.db::get_db_session::25 - pid:1 | Pool size: 64 Connections in pool: 1 Current Overflow: -61 Current Checked out connections: 2 | True True
INFO: 2024-09-12 10:25:32 - sellingexpert.utils.response_util::log_response::155 - 172.22.121.60:31551 - "GET http://172.22.121.60:32100/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:25:32.070399 - duration:0.055s
2024-09-12 10:26:23,329 INFO sqlalchemy.pool.impl.AsyncAdaptedQueuePool Disconnection detected on checkout, invalidating all pooled connections prior to current timestamp (reason: InvalidatePoolError())
[12/Sep/2024 10:26:23] INFO - Disconnection detected on checkout, invalidating all pooled connections prior to current timestamp (reason: InvalidatePoolError())
2024-09-12 10:26:23,330 INFO sqlalchemy.pool.impl.AsyncAdaptedQueuePool Invalidate connection <AdaptedConnection <aiomysql.connection.Connection object at 0x70568f73edd0>> (reason: InvalidatePoolError:())
[12/Sep/2024 10:26:23] INFO - Invalidate connection <AdaptedConnection <aiomysql.connection.Connection object at 0x70568f73edd0>> (reason: InvalidatePoolError:())
INFO: 2024-09-12 10:26:23 - sellingexpert.utils.response_util::log_response::155 - 10.233.79.115:37050 - "GET http://www.dev.ai4x.cloud:32494/selling/api/v1/customer/ HTTP/1.1" 200 OK - start:2024-09-12 10:10:24.236866 - duration:959.201s
5