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.
