Hi there -
thanks for the clear example. I just ran it against a several PG databases,
including a PG 13 and PG 12 on the local network, and I am not observing any
delay of that magnitude, SQL output with timestamps follow.
what OS are you running on ? I would say you might want to try
replicating these commands to plain asyncpg, but that will not necessarily
produce the same sequence as we use prepared statements explicitly in all
cases, or try running the equivalent commands with psycopg2 to see if there's
some database-specific issue going on. but you're running against a vanilla
docker container so that's a little strange, try running the script from your
workstation instead perhaps.
2021-03-25 08:56:24,722 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-03-25 08:56:24,723 INFO sqlalchemy.engine.Engine INSERT INTO "TableA" (a)
VALUES (%s) RETURNING "TableA".id
2021-03-25 08:56:24,723 INFO sqlalchemy.engine.Engine [generated in 0.00023s]
('ONE',)
2021-03-25 08:56:24,754 DEBUG sqlalchemy.engine.Engine Col ('id',)
2021-03-25 08:56:24,754 DEBUG sqlalchemy.engine.Engine Row (1,)
2021-03-25 08:56:24,754 INFO sqlalchemy.engine.Engine COMMIT
2021-03-25 08:56:24,758 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-03-25 08:56:24,759 INFO sqlalchemy.engine.Engine INSERT INTO "TableB" (b,
c) VALUES (%s, %s) RETURNING "TableB".id
2021-03-25 08:56:24,759 INFO sqlalchemy.engine.Engine [generated in 0.00019s]
('THREE', 'FIVE')
2021-03-25 08:56:24,767 DEBUG sqlalchemy.engine.Engine Col ('id',)
2021-03-25 08:56:24,767 DEBUG sqlalchemy.engine.Engine Row (1,)
2021-03-25 08:56:24,768 INFO sqlalchemy.engine.Engine COMMIT
2021-03-25 08:56:24,770 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-03-25 08:56:24,771 INFO sqlalchemy.engine.Engine INSERT INTO "TableB" (b,
c) VALUES (%s, %s) RETURNING "TableB".id
2021-03-25 08:56:24,771 INFO sqlalchemy.engine.Engine [cached since 0.01149s
ago] ('FOUR', 'SIX')
2021-03-25 08:56:24,772 DEBUG sqlalchemy.engine.Engine Col ('id',)
2021-03-25 08:56:24,772 DEBUG sqlalchemy.engine.Engine Row (2,)
2021-03-25 08:56:24,772 INFO sqlalchemy.engine.Engine COMMIT
On Thu, Mar 25, 2021, at 8:31 AM, Michaël Van de Steene wrote:
> Hi everyone,
>
> We recently started using sqlalchemy in combination with asyncpg and are
> observing some behaviour we can't quite figure out. I hope this is the right
> place to get help, if it would be better addressed elsewhere please let me
> know.
>
> To frame the issue, we have a table with several enum columns. The first time
> we access this table, there is a roughly 600 ms delay before any results are
> returned. This seems to apply both for insert and select operations. After
> that first access, everything seems speedy returning in just a few
> milliseconds.
>
> I've created a short example application to show this problem:
> import asyncio
> import enum
> from sqlalchemy import Enum, Column, Integer
> from sqlalchemy.ext.asyncio import AsyncSession, create_async_engine
> from sqlalchemy.ext.declarative import declarative_base
> from sqlalchemy.orm import sessionmaker
>
> Base = declarative_base()
>
>
> class A(enum.Enum):
> ONE = 1
> TWO = 2
>
>
> class B(enum.Enum):
> THREE = 3
> FOUR = 4
>
>
> class C(enum.Enum):
> FIVE = 5
> SIX = 6
>
>
> class RecordA(Base):
> __tablename__ = "TableA"
>
> id = Column(Integer, primary_key=True, autoincrement=True)
> a = Column(Enum(A))
>
>
> class RecordB(Base):
> __tablename__ = "TableB"
>
> id = Column(Integer, primary_key=True, autoincrement=True)
> b = Column(Enum(B))
> c = Column(Enum(C))
>
>
> async def main(db_url):
> engine = create_async_engine(db_url, echo="debug")
> Session = sessionmaker(engine, expire_on_commit=False,
> class_=AsyncSession)
>
> async with engine.begin() as conn:
> await conn.run_sync(Base.metadata.drop_all)
> await conn.run_sync(Base.metadata.create_all)
>
> async with Session() as session:
> async with session.begin():
> session.add(RecordA(a=A.ONE))
> async with session.begin():
> session.add(RecordB(b=B.THREE, c=C.FIVE))
> async with session.begin():
> session.add(RecordB(b=B.FOUR, c=C.SIX))
>
>
> asyncio.run(main(
> "postgresql+asyncpg://postgres:example@host.docker.internal/postgres"))
>
> The logging of the three insert operations shows:
> 2021-03-25 12:14:10,224 INFO sqlalchemy.engine.Engine BEGIN (implicit)
> 2021-03-25 12:14:10,225 INFO sqlalchemy.engine.Engine INSERT INTO "TableA"
> (a) VALUES (%s) RETURNING "TableA".id
> 2021-03-25 12:14:10,225 INFO sqlalchemy.engine.Engine [generated in 0.00011s]
> ('ONE',)
> 2021-03-25 12:14:10,296 DEBUG sqlalchemy.engine.Engine Col ('id',)
> 2021-03-25 12:14:10,296 DEBUG sqlalchemy.engine.Engine Row (1,)
> 2021-03-25 12:14:10,296 INFO sqlalchemy.engine.Engine COMMIT
> 2021-03-25 12:14:10,299 INFO sqlalchemy.engine.Engine BEGIN (implicit)
> 2021-03-25 12:14:10,299 INFO sqlalchemy.engine.Engine INSERT INTO "TableB"
> (b, c) VALUES (%s, %s) RETURNING "TableB".id
> 2021-03-25 12:14:10,299 INFO sqlalchemy.engine.Engine [generated in 0.00012s]
> ('THREE', 'FIVE')
> 2021-03-25 12:14:10,906 DEBUG sqlalchemy.engine.Engine Col ('id',)
> 2021-03-25 12:14:10,906 DEBUG sqlalchemy.engine.Engine Row (1,)
> 2021-03-25 12:14:10,906 INFO sqlalchemy.engine.Engine COMMIT
> 2021-03-25 12:14:10,924 INFO sqlalchemy.engine.Engine BEGIN (implicit)
> 2021-03-25 12:14:10,924 INFO sqlalchemy.engine.Engine INSERT INTO "TableB"
> (b, c) VALUES (%s, %s) RETURNING "TableB".id
> 2021-03-25 12:14:10,924 INFO sqlalchemy.engine.Engine [cached since 0.625s
> ago] ('FOUR', 'SIX')
> 2021-03-25 12:14:10,926 DEBUG sqlalchemy.engine.Engine Col ('id',)
> 2021-03-25 12:14:10,926 DEBUG sqlalchemy.engine.Engine Row (2,)
> 2021-03-25 12:14:10,926 INFO sqlalchemy.engine.Engine COMMIT
>
> I've highlighted the timestamps showing the 600 ms delay in red.
> It seems as if:
> * An insert with just 1 enum does not incur delay
> * An insert with 2 enums incurs delays
> * A subsequent insert using those same enums doesn't incur delay
> I'm at a loss to explain this behaviour. As I mentioned we're quite new to
> SQLAlchemy. Is there anything we're doing wrong?
>
> The output is generated using:
> * PostgreSQL 13.2
> * Python 3.9.2
> * SQLAlchemy 1.4.2
> * Asyncpg 0.22.0
>
> Finally, run instructions using docker just in case it can help to quickly
> reproduce:
> 1. Save the example as `asyncpg_enum.py` in the current directory
> 2. Run docker run -d --name=postgres -e POSTGRES_PASSWORD="example" -p
> 5432:5432 postgres
> 3. Run docker run -it -v ${PWD}/asyncpg_enum.py:/asyncpg_enum.py python bash
> -c 'pip install sqlalchemy asyncpg && python /asyncpg_enum.py'
> Any insight or things to check would be appreciated.
>
> Thanks,
> Michael
>
> --
> SQLAlchemy -
> The Python SQL Toolkit and Object Relational Mapper
>
> http://www.sqlalchemy.org/
>
> To post example code, please provide an MCVE: Minimal, Complete, and
> Verifiable Example. See http://stackoverflow.com/help/mcve for a full
> description.
> ---
> You received this message because you are subscribed to the Google Groups
> "sqlalchemy" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to sqlalchemy+unsubscr...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/sqlalchemy/65748bd4-bea6-4e07-b7ce-c1a8c5a91c98n%40googlegroups.com
>
> <https://groups.google.com/d/msgid/sqlalchemy/65748bd4-bea6-4e07-b7ce-c1a8c5a91c98n%40googlegroups.com?utm_medium=email&utm_source=footer>.
--
SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
http://www.sqlalchemy.org/
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable
Example. See http://stackoverflow.com/help/mcve for a full description.
---
You received this message because you are subscribed to the Google Groups
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to sqlalchemy+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/sqlalchemy/0293dd1a-9e0b-4d2b-b377-62faa4c77a2a%40www.fastmail.com.
