I can reproduce using postgres in docker. About 1s of delay 2021-03-25 20:22:12,488 INFO sqlalchemy.engine.Engine INSERT INTO "TableA" (a) VALUES (?) RETURNING "TableA".id 2021-03-25 20:22:12,488 INFO sqlalchemy.engine.Engine [generated in 0.00091s] ('ONE',) 2021-03-25 20:22:12,631 DEBUG sqlalchemy.engine.Engine Col ('id',) 2021-03-25 20:22:12,632 DEBUG sqlalchemy.engine.Engine Row (1,) 2021-03-25 20:22:12,632 INFO sqlalchemy.engine.Engine COMMIT 2021-03-25 20:22:12,637 INFO sqlalchemy.engine.Engine BEGIN (implicit) 2021-03-25 20:22:12,639 INFO sqlalchemy.engine.Engine INSERT INTO "TableB" (b, c) VALUES (?, ?) RETURNING "TableB".id 2021-03-25 20:22:12,639 INFO sqlalchemy.engine.Engine [generated in 0.00055s] ('THREE', 'FIVE') 2021-03-25 20:22:13,692 DEBUG sqlalchemy.engine.Engine Col ('id',) 2021-03-25 20:22:13,693 DEBUG sqlalchemy.engine.Engine Row (1,) 2021-03-25 20:22:13,694 INFO sqlalchemy.engine.Engine COMMIT 2021-03-25 20:22:13,700 INFO sqlalchemy.engine.Engine BEGIN (implicit) 2021-03-25 20:22:13,701 INFO sqlalchemy.engine.Engine INSERT INTO "TableB" (b, c) VALUES (?, ?) RETURNING "TableB".id 2021-03-25 20:22:13,701 INFO sqlalchemy.engine.Engine [cached since 1.063s ago] ('FOUR', 'SIX') 2021-03-25 20:22:13,705 DEBUG sqlalchemy.engine.Engine Col ('id',) 2021-03-25 20:22:13,706 DEBUG sqlalchemy.engine.Engine Row (2,) 2021-03-25 20:22:13,706 INFO sqlalchemy.engine.Engine COMMIT
On Thursday, 25 March 2021 at 20:18:59 UTC+1 Federico Caselli wrote: > Hi, > > I've tried the script and I also cannot reproduce it: > > py3.7 + pg 13.1 (non-docker) on windows > > 2021-03-25 19:35:15,977 INFO sqlalchemy.engine.Engine BEGIN (implicit) > 2021-03-25 19:35:15,979 INFO sqlalchemy.engine.Engine INSERT INTO "TableA" > (a) VALUES (?) RETURNING "TableA".id > 2021-03-25 19:35:15,980 INFO sqlalchemy.engine.Engine [generated in > 0.00080s] ('ONE',) > 2021-03-25 19:35:15,999 DEBUG sqlalchemy.engine.Engine Col ('id',) > 2021-03-25 19:35:16,000 DEBUG sqlalchemy.engine.Engine Row (1,) > 2021-03-25 19:35:16,001 INFO sqlalchemy.engine.Engine COMMIT > 2021-03-25 19:35:16,004 INFO sqlalchemy.engine.Engine BEGIN (implicit) > 2021-03-25 19:35:16,006 INFO sqlalchemy.engine.Engine INSERT INTO "TableB" > (b, c) VALUES (?, ?) RETURNING "TableB".id > 2021-03-25 19:35:16,006 INFO sqlalchemy.engine.Engine [generated in > 0.00070s] ('THREE', 'FIVE') > 2021-03-25 19:35:16,014 DEBUG sqlalchemy.engine.Engine Col ('id',) > 2021-03-25 19:35:16,014 DEBUG sqlalchemy.engine.Engine Row (1,) > 2021-03-25 19:35:16,015 INFO sqlalchemy.engine.Engine COMMIT > 2021-03-25 19:35:16,016 INFO sqlalchemy.engine.Engine BEGIN (implicit) > 2021-03-25 19:35:16,017 INFO sqlalchemy.engine.Engine INSERT INTO "TableB" > (b, c) VALUES (?, ?) RETURNING "TableB".id > 2021-03-25 19:35:16,017 INFO sqlalchemy.engine.Engine [cached since > 0.0114s ago] ('FOUR', 'SIX') > 2021-03-25 19:35:16,018 DEBUG sqlalchemy.engine.Engine Col ('id',) > 2021-03-25 19:35:16,019 DEBUG sqlalchemy.engine.Engine Row (2,) > 2021-03-25 19:35:16,020 INFO sqlalchemy.engine.Engine COMMIT > > On Thursday, 25 March 2021 at 19:33:57 UTC+1 Michaël Van de Steene wrote: > >> *what happens if you run the asyncio.run() part in a loop? is the 700 >> ms every time ? * >> Yes, it happens each time. >> >> I also just ran the same test on a different device, a raspberry pi as >> that's what I had quickly available. Logging from that run is attached >> below. >> There's a slowdown at two points, and it's substantially larger. This >> slowdown in the first query is also present in the original log, it's just >> less noticeable (70 ms). >> >> Gives me the impression the slowdown is caused by some CPU bound process, >> as the raspberry pi's performance is a lot worse than my workstation. >> >> 2021-03-25 18:26:23,807 INFO sqlalchemy.engine.Engine BEGIN (implicit) >> 2021-03-25 18:26:23,810 INFO sqlalchemy.engine.Engine INSERT INTO >> "TableA" (a) VALUES (%s) RETURNING "TableA".id >> 2021-03-25 18:26:23,811 INFO sqlalchemy.engine.Engine [generated in >> 0.00055s] ('ONE',) >> 2021-03-25 18:26:24,274 DEBUG sqlalchemy.engine.Engine Col ('id',) >> 2021-03-25 18:26:24,275 DEBUG sqlalchemy.engine.Engine Row (1,) >> 2021-03-25 18:26:24,276 INFO sqlalchemy.engine.Engine COMMIT >> 2021-03-25 18:26:24,289 INFO sqlalchemy.engine.Engine BEGIN (implicit) >> 2021-03-25 18:26:24,291 INFO sqlalchemy.engine.Engine INSERT INTO >> "TableB" (b, c) VALUES (%s, %s) RETURNING "TableB".id >> 2021-03-25 18:26:24,291 INFO sqlalchemy.engine.Engine [generated in >> 0.00056s] ('THREE', 'FIVE') >> 2021-03-25 18:26:28,102 DEBUG sqlalchemy.engine.Engine Col ('id',) >> 2021-03-25 18:26:28,102 DEBUG sqlalchemy.engine.Engine Row (1,) >> 2021-03-25 18:26:28,103 INFO sqlalchemy.engine.Engine COMMIT >> 2021-03-25 18:26:28,115 INFO sqlalchemy.engine.Engine BEGIN (implicit) >> 2021-03-25 18:26:28,116 INFO sqlalchemy.engine.Engine INSERT INTO >> "TableB" (b, c) VALUES (%s, %s) RETURNING "TableB".id >> 2021-03-25 18:26:28,116 INFO sqlalchemy.engine.Engine [cached since >> 3.825s ago] ('FOUR', 'SIX') >> 2021-03-25 18:26:28,119 DEBUG sqlalchemy.engine.Engine Col ('id',) >> 2021-03-25 18:26:28,119 DEBUG sqlalchemy.engine.Engine Row (2,) >> 2021-03-25 18:26:28,120 INFO sqlalchemy.engine.Engine COMMIT >> On Thursday, 25 March 2021 at 19:25:11 UTC+1 Mike Bayer wrote: >> >>> 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+...@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/450cfa12-c79f-473e-9d38-b77749e1a6a8n%40googlegroups.com.