Memory leak when using command_timeout

[CaselIT]

• asyncpg version: 0.24
• PostgreSQL version: 13, 12
• Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
  the issue with a local PostgreSQL install?:
• Python version: 3.9.5
• Platform: windows, linux
• Do you use pgbouncer?: no
• Did you install asyncpg with pip?: yes
• If you built asyncpg locally, which version of Cython did you use?: no
• Can the issue be reproduced under both asyncio and
  uvloop?:

This was initially reported on sqlalchemy by @mvbrn here sqlalchemy/sqlalchemy#7058 and followed up at sqlalchemy/sqlalchemy#7059, but we can reproduce the issue without using sqlalchemy.

Here is the test I'm running:

import asyncio
import gc
import tracemalloc
import asyncpg

DB_URL_PG = "postgresql://scott:tiger@127.0.0.1:5432/test"


async def job(wait_for=0.01):
    # just do some dummy stuff
    conn = await asyncpg.connect(DB_URL_PG, command_timeout=60 * 1000)
    await conn.execute(f"select 1;")
    await conn.execute(f"select pg_sleep({wait_for});")
    await conn.close()


async def run():
    tracemalloc.start()
    snapshot1 = tracemalloc.take_snapshot()

    num_rounds = 100
    num_jobs = 10

    for _ in range(num_rounds):
        await asyncio.gather(*(job() for i in range(num_jobs)))
        print(_)

    snapshot2 = tracemalloc.take_snapshot()
    top_stats = snapshot2.compare_to(snapshot1, "lineno")

    print("[ Top 10 differences ]")
    for stat in top_stats[:10]:
        print(stat)

    print("Running garbage collection")

    gc.collect()

    print("Stats after collection")

    snapshot2 = tracemalloc.take_snapshot()
    top_stats = snapshot2.compare_to(snapshot1, "lineno")

    print("[ Top 10 differences after gc ]")
    for stat in top_stats[:10]:
        print(stat)

    top_stats = snapshot2.statistics("lineno")

    print("[ Top 10 - FINAL stats ]")
    for stat in top_stats[:10]:
        print(stat)


if __name__ == "__main__":
    asyncio.run(run())

Running uses quite a bit of ram an the final print, on windows is something like

[ Top 10 differences ]
\lib\asyncio\windows_events.py:449: size=31.3 MiB (+31.3 MiB), count=1001 (+1001), average=32.0 KiB
\lib\asyncio\proactor_events.py:269: size=1776 KiB (+1776 KiB), count=22002 (+22002), average=83 B
\lib\site-packages\asyncpg\connect_utils.py:705: size=1773 KiB (+1773 KiB), count=16756 (+16756), average=108 B
\lib\asyncio\locks.py:174: size=711 KiB (+711 KiB), count=4000 (+4000), average=182 B
\lib\asyncio\windows_events.py:812: size=649 KiB (+649 KiB), count=2001 (+2001), average=332 B
\lib\asyncio\events.py:80: size=588 KiB (+588 KiB), count=1050 (+1050), average=573 B
\lib\asyncio\base_events.py:1890: size=577 KiB (+577 KiB), count=1000 (+1000), average=591 B
\lib\asyncio\windows_events.py:457: size=552 KiB (+552 KiB), count=6036 (+6036), average=94 B
\lib\asyncio\windows_events.py:434: size=299 KiB (+299 KiB), count=500 (+500), average=613 B
\lib\asyncio\base_events.py:596: size=297 KiB (+297 KiB), count=500 (+500), average=608 B

Removing the command_timeout no noticeable leak is observed:

[ Top 10 differences ]
\lib\asyncio\windows_events.py:449: size=645 KiB (+645 KiB), count=21 (+21), average=30.7 KiB
<string>:1: size=96.0 KiB (+96.0 KiB), count=1023 (+1023), average=96 B
\lib\site-packages\asyncpg\connect_utils.py:705: size=37.6 KiB (+37.6 KiB), count=339 (+339), average=114 B
\lib\asyncio\proactor_events.py:269: size=36.1 KiB (+36.1 KiB), count=441 (+441), average=84 B
\lib\asyncio\events.py:80: size=22.3 KiB (+22.3 KiB), count=53 (+53), average=432 B
\lib\asyncio\base_events.py:1890: size=19.7 KiB (+19.7 KiB), count=30 (+30), average=672 B
\lib\asyncio\windows_events.py:812: size=16.6 KiB (+16.6 KiB), count=44 (+44), average=387 B
\lib\asyncio\base_events.py:1854: size=11.1 KiB (+11.1 KiB), count=17 (+17), average=670 B
\lib\asyncio\windows_events.py:457: size=10.9 KiB (+10.9 KiB), count=120 (+120), average=93 B
\lib\asyncio\locks.py:174: size=10.1 KiB (+10.1 KiB), count=72 (+72), average=144 B

[elprans]

This seems to be a windows proactor bug in asyncio. I can't reproduce the leak on Linux.

[CaselIT]

@zzzeek was reproducing it also on linux. Could you share the details?

@elprans which version of python you used on linux?

[elprans]

Actually, I think I found the leak. See #831

[CaselIT]

Thanks for looking into it.

I cannot immediately test it on windows since I don't have all the cython build chain installed, sorry.
If you can produce a wheel without much hassle, I can test it.

[zzzeek]

this does reproduce for me on linux, running fedora 34.

[0xD09CD196D188D0B0]

Same for Ubuntu 20.04