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:[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/f797e657-42a2-4607-a5c9-e98f248f0493n%40googlegroups.com.
