what happens if you run the asyncio.run() part in a loop? is the 700 ms every
time ?
On Thu, Mar 25, 2021, at 1:54 PM, Michaël Van de Steene wrote:
> Sorry for the slow reply, been dealing with a few other issues while also
> working on this.
> To confirm your question: using PG12 and Python 3.7 I do see the slowdown.
>
> Since then I've taken to some extra tests (all using SQLAlchemy 1.4.2 and
> asyncpg 0.2.2.0)
> 1. PG12.6 (no docker) with Python 3.8 (in docker): 700 ms slowdown
> 2. PG12.6 (no docker) with Python 3.9 (in docker): 700 ms slowdown
> 3. PG12.6 (no docker) with Python 3.8.8 (no docker): 700 ms slowdown
> * I am also getting a 'OSError: [Errno 9] Bad file descriptor' error in
> this configuration. Seems as if there is still communication with the
> database when the asyncio loop is torn down.
> Figure this may be related to the compile process. I've installed it from
> source using ./configure --enable-optimizations
> 4. PG12.6 (no docker) with Python 3.7.10 (no docker): 700 ms slowdown
> In short, I am always seeing this delay on the second insert in the example
> script regardless of python version and use of docker.
>
> In all these tests the PG instance was running on a Ubuntu 20.04.2 virtual
> machine.
> The python (and docker) side of things was running in Debian 10 (in WSL2 on a
> windows machine, if that matters).
>
> In an attempt to exclude the WSL2 environment, I also attempted to run
> (dockerised) python in the same Ubuntu 20.04.2 virtual machine but that too
> is showing the delay.
> On Thursday, 25 March 2021 at 15:57:17 UTC+1 Mike Bayer wrote:
>> __
>> 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:[email protected]/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 [email protected].
>>>>> 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 [email protected].
>>> 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 [email protected].
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/sqlalchemy/b407388e-fc54-4b3f-8376-f86f6de5c530n%40googlegroups.com
>
> <https://groups.google.com/d/msgid/sqlalchemy/b407388e-fc54-4b3f-8376-f86f6de5c530n%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 [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/sqlalchemy/fa1d18a3-8d1a-4bdf-8252-b6673c4da437%40www.fastmail.com.
