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:[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/450cfa12-c79f-473e-9d38-b77749e1a6a8n%40googlegroups.com.
