Async SqlAlchemy session after saving takes too much time to return

Question

I'm moving from SQLAlchemy to SQLAlchemy[async] using postgresql as my DB. I'm following SQL Alchemy documentation https://docs.sqlalchemy.org/en/14/_modules/examples/asyncio/async_orm.html

After making all changes on the code my tests got extremely slow

I added a bunch of logs in order to print where this time is lost. I also profiled but cProfile does not show anything relatable.

I got this delay in the code only after an insert. On the test I shared I do a insert and then a retrieve, and it only happens on after a session is used with a add operation.

engine = create_async_engine(DATABASE_URL,
                             pool_size=20,
                             max_overflow=2,
                             pool_recycle=300,
                             pool_pre_ping=True,
                             pool_use_lifo=True)
async_session = sessionmaker(engine, expire_on_commit=False, class_=AsyncSession)


@asynccontextmanager
async def session_scope() -> AsyncSession:
    """
    Context manager for API DB Sessions
    """
    try:
        async with async_session() as session:
            await session.begin()
            logger.info('Yielding session')
            yield session
            logger.info('Returned session')
            logger.info('Pre commit')
            await session.commit()
            logger.info('Commit finished')
    except Exception as exc:  # pylint: disable=W0703
        logger.exception('Exception on session')
        await session.rollback()
        raise exc 

This is my client

async def create_sync_job(entity: SyncJob) -> SyncJob:
    """
    Method for SyncJob creation
    :param sync_job:
    :return: SyncJob
    """
    start_time = time.time()
    async with session_scope() as session:
        logger.info(f'time spend in get session {time.time() - start_time}')
        start_time = time.time()
        session.add(entity)
        logger.info(f'time spend in saving {time.time() - start_time}')
        logger.info(f'Created sync job for user {entity.user_id} and {entity.pos_id}')
        return entity

And my test

    async def test_create_sync_job(self):
        start_time = time.time()
        sync_job = sync_job_factory()
        start_time2 = time.time()
        created = await create_sync_job(sync_job)
        end_time = time.time()
        logger.info(f'spend time creating object {end_time - start_time2}')
        self.assertIsNotNone(created)
        end_time = time.time()
        logger.info(f'spend time {end_time-start_time}')
        created_db = await get_listing_sync_job_by_user(user_id=created.user_id)
        self.assertIsNotNone(created)

My test works well, but there is a massive time window between after the async with session.begin(): returns the control. This is between message Returned session and Pre commit. I have a big number of tests to run and this has made my tests very slow comparing when it was not async.

{"@timestamp":"2022-02-17T15:08:34.496Z","log.level":"info","message":"Yielding session"}
{"@timestamp":"2022-02-17T15:08:34.496Z","log.level":"info","message":"time spend in get session 0.0013709068298339844"}
{"@timestamp":"2022-02-17T15:08:34.496Z","log.level":"info","message":"time spend in saving 2.288818359375e-05"}
{"@timestamp":"2022-02-17T15:08:34.496Z","log.level":"info","message":"Created sync job for user 61abcde4-0248-4c3f-a56e-4bdd4b6e20b0 and baea6703-87e3-4e5d-a318-5b67f4749c3c"}
{"@timestamp":"2022-02-17T15:08:34.496Z","log.level":"info","message":"Returned session"}
{"@timestamp":"2022-02-17T15:08:44.257Z","log.level":"info","message":"Pre commit"}
{"@timestamp":"2022-02-17T15:08:44.258Z","log.level":"info","message":"Commit finished"}
{"@timestamp":"2022-02-17T15:08:44.259Z","log.level":"info","message":"spend time creating object 9.763978958129883"}
{"@timestamp":"2022-02-17T15:08:44.259Z","log.level":"info","message":"spend time 9.768352031707764"}
{"@timestamp":"2022-02-17T15:08:44.259Z","log.level":"info","message":"Yielding session"}
{"@timestamp":"2022-02-17T15:08:44.274Z","log.level":"info","message":"Returned session"}
{"@timestamp":"2022-02-17T15:08:44.276Z","log.level":"info","message":"Pre commit"}
{"@timestamp":"2022-02-17T15:08:44.276Z","log.level":"info","message":"Commit finished"}

edit: formatting in code