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: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+...@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/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 sqlalchemy+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/sqlalchemy/fa1d18a3-8d1a-4bdf-8252-b6673c4da437%40www.fastmail.com.