Execution time differing a lot form ANALYZE EXPLAIN

[Andarius]

• asyncpg version: 0.22.0
• PostgreSQL version: 12-alpine
• Do you use a PostgreSQL SaaS? If so, which? Can you reproduce
  the issue with a local PostgreSQL install?: No
• Python version: 3.8.8
• Platform: KDE
• Do you use pgbouncer?: no
• Did you install asyncpg with pip?: yes
• If you built asyncpg locally, which version of Cython did you use?: -
• Can the issue be reproduced under both asyncio and
  uvloop?: yes

I have the following request:

with _test as (
    SELECT ex.id,
        ex.user_id,
       COALESCE(tags.tags, '{}') as tags,
       COALESCE(muscles.muscles, '{}') as muscles
    from exercises ex, 
    lateral (
        SELECT array_agg(t.id) as tags
        from tags t
        inner join exercise_tags e on t.id = e.tag_id
        where e.exercise_id = ex.id
    ) tags,
    lateral (
        SELECT array_agg(t.id) as muscles
        FROM muscles t
        inner join exercise_muscles e on t.id = e.muscle_id
        where e.exercise_id = ex.id
    ) muscles
)
SELECT * from _test ex
where user_id = $1

When running it using fetch it takes about 3 seconds to complete which is way more that the execution time given by the EXPLAIN (~ 10ms). What could be the cause of this ?

Here is the corresponding EXPLAIN:

| Nested Loop  (cost=10.53..1312.70 rows=123 width=96) (actual time=0.128..8.321 rows=123 loops=1)                                         |
|   ->  Nested Loop  (cost=4.29..541.54 rows=123 width=64) (actual time=0.057..3.378 rows=123 loops=1)                                     |
|         ->  Seq Scan on exercises ex  (cost=0.00..10.09 rows=123 width=32) (actual time=0.011..0.068 rows=123 loops=1)                   |
|               Filter: (user_id = 'd0792a59-686c-461c-bf6f-6f886e86af0a'::uuid)                                                           |
|               Rows Removed by Filter: 124                                                                                                |
|         ->  Aggregate  (cost=4.29..4.30 rows=1 width=32) (actual time=0.026..0.026 rows=1 loops=123)                                     |
|               ->  Hash Join  (cost=2.30..4.28 rows=2 width=16) (actual time=0.021..0.024 rows=1 loops=123)                               |
|                     Hash Cond: (t.id = e.tag_id)                                                                                         |
|                     ->  Seq Scan on tags t  (cost=0.00..1.77 rows=77 width=16) (actual time=0.002..0.009 rows=76 loops=40)               |
|                     ->  Hash  (cost=2.28..2.28 rows=2 width=16) (actual time=0.016..0.016 rows=1 loops=123)                              |
|                           Buckets: 1024  Batches: 1  Memory Usage: 8kB                                                                   |
|                           ->  Seq Scan on exercise_tags e  (cost=0.00..2.28 rows=2 width=16) (actual time=0.013..0.014 rows=1 loops=123) |
|                                 Filter: (exercise_id = ex.id)                                                                            |
|                                 Rows Removed by Filter: 101                                                                              |
|   ->  Aggregate  (cost=6.24..6.25 rows=1 width=32) (actual time=0.039..0.039 rows=1 loops=123)                                           |
|         ->  Hash Join  (cost=4.99..6.23 rows=4 width=4) (actual time=0.037..0.037 rows=0 loops=123)                                      |
|               Hash Cond: (t_1.id = e_1.muscle_id)                                                                                        |
|               ->  Seq Scan on muscles t_1  (cost=0.00..1.18 rows=18 width=4) (actual time=0.001..0.003 rows=18 loops=10)                 |
|               ->  Hash  (cost=4.94..4.94 rows=4 width=4) (actual time=0.035..0.035 rows=0 loops=123)                                     |
|                     Buckets: 1024  Batches: 1  Memory Usage: 8kB                                                                         |
|                     ->  Seq Scan on exercise_muscles e_1  (cost=0.00..4.94 rows=4 width=4) (actual time=0.033..0.034 rows=0 loops=123)   |
|                           Filter: (exercise_id = ex.id)                                                                                  |
|                           Rows Removed by Filter: 235                                                                                    |
| Planning Time: 1.316 ms                                                                                                                  |
| Execution Time: 8.388 ms    

[elprans]

asyncpg uses prepared statements by default, and it is possible that the distribution of data in your tables is such that the plan chosen for this query is extremely inefficient for a given set of arguments. You can exempt the query from the shared prepared statement cache by creating an explicit prepared statement every time you run the query:

ps = await conn.prepare(query)
data = await ps.fetch(**args)

[Andarius]

I tried that but did not see any change.
Each time I receive a new request I get the connection from a pool with async with pg_pool.acquire() as conn.
Does that defeat the purpose of prepare ?

[elprans]

Hm. That's odd. I don't see any other reason other than a bad plan. Does the query actually show up in the slowlog (log_min_duration_statement)?

[Andarius]

Actually debugging using log_min_duration_statement showed me that it was WITH RECURSIVE typeinfo_tree( ... that was taking most of the time, not the request itself.
Thanks !

[elprans]

You might want to turn PostgreSQL's JIT off (jit=off). It's known to behave badly with asyncpg's introspection queries and is quite useless in general (I'm still amazed they turned it on by default).

[Andarius]

All my requests are 10x faster now... Wish I knew this option was on before. Thanks a lot !