Asyncpg: Using conn pool in high-freq app, conn reset is too slow; customize reset actions?

[jmehnle]

• asyncpg version: 0.15.0
• PostgreSQL version: 9.5.10
• Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
  the issue with a local PostgreSQL install?: AWS RDS
• Python version: 3.5.2
• Platform: Ubuntu 16.04, Linux 4.4.0
• Do you use pgbouncer?: no
• Did you install asyncpg with pip?: yes
• If you built asyncpg locally, which version of Cython did you use?: CPython 3.5.2
• Can the issue be reproduced under both asyncio and
  uvloop?: have not tried uvloop; choice of loop implementation probably irrelevant

I have a high-frequency app that implements a DNS server. It runs in a single process, with a connection pool with a maximum of 8 connections. It receives dozens to hundreds of requests per second, and each request acquires a DB connection from the pool (using async with db_pool.acquire()) and issues a single DB query. This query is probably irrelevant to this issue, however I'm reproducing it here to give perspective to the performance issue:

SELECT
    sender_detail.id,
    approval.approval_state
FROM
    approval
    INNER JOIN sender_detail
        ON approval.sender_detail_id = sender_detail.id
    INNER JOIN domain
        ON sender_detail.domain_id = domain.id
WHERE
    approval.organization_id = $1 and
    sender_detail.sender_id  = $2 and
    domain.punycode_domain   = $3

The query plan is:

                                                                  QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop  (cost=0.87..66.21 rows=1 width=16) (actual time=0.041..0.049 rows=1 loops=1)
   ->  Nested Loop  (cost=0.44..60.39 rows=1 width=24) (actual time=0.033..0.040 rows=1 loops=1)
         ->  Seq Scan on approval  (cost=0.00..1.09 rows=7 width=16) (actual time=0.009..0.011 rows=6 loops=1)
               Filter: (organization_id = 24)
         ->  Index Scan using sender_detail_pkey on sender_detail  (cost=0.44..8.46 rows=1 width=16) (actual time=0.003..0.003 rows=0 loops=6)
               Index Cond: (id = approval.sender_detail_id)
               Filter: (sender_id = 56)
               Rows Removed by Filter: 0
   ->  Index Scan using domain_pkey on domain  (cost=0.43..5.80 rows=1 width=8) (actual time=0.006..0.006 rows=1 loops=1)
         Index Cond: (id = sender_detail.domain_id)
         Filter: (punycode_domain = 'REDACTED'::text)
 Planning time: 0.293 ms
 Execution time: 0.081 ms
(13 rows)

Now to the actual issue: Once the query completes, it sends out a DNS response and (implicitly, by way of exiting from async with db_pool.acquire()) returns the connection to the pool. This makes asyncpg reset the connection to make it available to the pool again. It's this resetting the connection that appears to be disproportionately slow:

stage:localhost:platform=> SELECT query, calls, total_time, min_time, max_time, mean_time FROM pg_stat_statements WHERE query not in ('<insufficient privilege>') and calls >= 10 ORDER BY total_time DESC LIMIT 2;
-[ RECORD 1 ]-----------------------------------------------------------------------
query      | SELECT pg_advisory_unlock_all();                                       +
           | CLOSE ALL;                                                             +
           |                                                                        +
           |     DO $$                                                              +
           |     BEGIN                                                              +
           |         PERFORM * FROM pg_listening_channels() LIMIT 1;                +
           |         IF FOUND THEN                                                  +
           |             UNLISTEN *;                                                +
           |         END IF;                                                        +
           |     END;                                                               +
           |     $$;                                                                +
           |                                                                        +
           | RESET ALL;
calls      | 70323
total_time | 3252.49900000025
min_time   | 0
max_time   | 5.917
mean_time  | 0.0462508567609464
-[ RECORD 2 ]-----------------------------------------------------------------------
query      |                                                                        +
           | SELECT                                                                 +
           |     sender_detail.id,                                                  +
           |     approval.approval_state                                            +
           | FROM                                                                   +
           |     approval                                                           +
           |     INNER JOIN sender_detail                                           +
           |         ON approval.sender_detail_id = sender_detail.id                +
           |     INNER JOIN domain                                                  +
           |         ON sender_detail.domain_id = domain.id                         +
           | WHERE                                                                  +
           |     approval.organization_id = $1 and                                  +
           |     sender_detail.sender_id  = $2 and                                  +
           |     domain.punycode_domain   = $3
calls      | 23426
total_time | 215.967999999933
min_time   | 0.005
max_time   | 3.893
mean_time  | 0.00921915820029028

(I'm currently investigating why connections are reset almost exactly 3 times as often as my business query is run, but that's besides the issue. And then of course I'm probably going to use a prepared statement to eliminate the query planning overhead.)

The mean time each connection reset takes, 0.046ms, is a whopping 5 times as long as the mean time each business query takes, 0.0092ms!

I can see why correctness goes before performance and why asyncpg thus would play it safe and reset a bunch of things when the connection is returned, but I'm really trying to optimize for speed here. As such it would be great if there was a way to customize the actions that asyncpg takes to reset the connection. In this particular case, really no reset actions whatsoever are needed. :-)

[elprans]

You can always subclass Connection to make await conn.reset() do nothing (or less). I don't think that explicit configurability on the base class here is a good idea.

[jmehnle]

I can do that, but how do I make the connection pool use that custom connection class?

[elprans]

Pass it as a connection_class keyword argument: https://magicstack.github.io/asyncpg/current/api/index.html#asyncpg.connection.connect

[elprans]

And then of course I'm probably going to use a prepared statement to eliminate the query planning overhead.

asyncpg does that by default, unless you've set statement_cache_size to 0.

[jmehnle]

Excellent, this worked for me:

import asyncpg.connection

# Inhibit connection reset upon release to connection pool in order to avoid
# excessive overhead; see <https://github.com/MagicStack/asyncpg/issues/271>:
class NonresettingConnection(asyncpg.connection.Connection):
    async def reset(self, *, timeout=None):
        self._check_open()

        if self._protocol.is_in_transaction() or self._top_xact is not None:
            if self._top_xact is None or not self._top_xact._managed:
                # Managed transactions are guaranteed to __aexit__
                # correctly.
                self._loop.call_exception_handler({
                    'message': 'Resetting connection with an '
                               'active transaction {!r}'.format(self)
                })

            self._top_xact = None

Would you agree that the if self._protocol.is_in_transaction() or self._top_xact is not None: block is still appropriate? I removed everything else from the definition of the reset method.

[jmehnle]

BTW, I looked at my code and there's no way I'm explicitly resetting the connection three times for each pool checkout (see above). Is there something in asyncpg that might be doing that? I've mitigated that by skipping most of the resetting logic, but even then reset being called once really should be enough, right?

[elprans]

There should be exactly one reset for each acquire and release.

[elprans]

Would you agree that the if self._protocol.is_in_transaction() or self._top_xact is not None: block is still appropriate? I removed everything else from the definition of the reset method.

That checks for unclosed transactions on connection release. Can be skipped if you're sure you don't have that (i.e. all transactions are async with).

[jmehnle]

I can't reproduce the 3-resets-per-connection-checkout issue anymore right now, so let's leave it at that. I'm closing this issue. Thanks!