so with PG12 and python 3.7 you *do* or *do not* see the slowdown?
On Thu, Mar 25, 2021, at 10:45 AM, Michaël Van de Steene wrote:
> Thanks for the quick reply! It does appear to be an environment issue on my
> end then.
>
> I've already tried a few things:
> * Postgres 12
> * Python 3.7
> So far no dice. This was all within docker though, I'll try a few more things
> outside of the docker environment and report back.
>
> On Thursday, 25 March 2021 at 14:02:29 UTC+1 Mike Bayer wrote:
>> __
>> 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:exa...@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+...@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/8c817a6b-8e9b-41bd-940b-c91ceb6081a3n%40googlegroups.com
>
> <https://groups.google.com/d/msgid/sqlalchemy/8c817a6b-8e9b-41bd-940b-c91ceb6081a3n%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/0d86cc79-ad94-42aa-9730-40809994ef70%40www.fastmail.com.
