Re: Missing query plan for auto_explain.

[Matheus Martin <matheus.martin@xxxxxxxxxxxxxx>]

Understood. I have run a prepared statement with the query in question through `psql` and JIT was not used (see plan below), however please note that the long response times were never reproducible from `psql`, they only happen from our JDBC application.

                                                                                                                  QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31.41..31.41 rows=1 width=707) (actual time=4.421..4.442 rows=23 loops=1)
   Buffers: shared hit=827 dirtied=1
   ->  Sort  (cost=31.41..31.41 rows=1 width=707) (actual time=4.416..4.434 rows=23 loops=1)
         Sort Key: users.unique_identifier, user_realm.user_realm_id
         Sort Method: quicksort  Memory: 31kB
         Buffers: shared hit=827 dirtied=1
         ->  Nested Loop Left Join  (cost=7.84..31.40 rows=1 width=707) (actual time=1.154..4.232 rows=23 loops=1)
               Buffers: shared hit=824 dirtied=1
               ->  Nested Loop  (cost=7.55..24.94 rows=1 width=704) (actual time=1.090..3.725 rows=23 loops=1)
                     Join Filter: ((acl_allowed_user_realm_category.user_realm_category_id)::text = (user_realm_category.user_realm_category_id)::text)
                     Buffers: shared hit=757 dirtied=1
                     ->  Nested Loop  (cost=7.42..24.75 rows=1 width=209) (actual time=1.015..3.564 rows=23 loops=1)
                           Buffers: shared hit=711 dirtied=1
                           ->  Nested Loop  (cost=7.29..23.95 rows=1 width=204) (actual time=0.950..3.399 rows=23 loops=1)
                                 Buffers: shared hit=665 dirtied=1
                                 ->  Nested Loop  (cost=7.15..23.73 rows=1 width=200) (actual time=0.911..3.228 rows=23 loops=1)
                                       Buffers: shared hit=619 dirtied=1
                                       ->  Nested Loop  (cost=6.72..23.22 rows=1 width=200) (actual time=0.803..2.481 rows=23 loops=1)
                                             Buffers: shared hit=527
                                             ->  Nested Loop  (cost=6.44..22.42 rows=1 width=191) (actual time=0.669..2.249 rows=23 loops=1)
                                                   Buffers: shared hit=480
                                                   ->  Nested Loop  (cost=6.17..21.55 rows=1 width=194) (actual time=0.616..2.091 rows=23 loops=1)
                                                         Join Filter: ((organisation.organisation_id)::text = (acl_allowed_organisation.organisation_id)::text)
                                                         Buffers: shared hit=411
                                                         ->  Nested Loop  (cost=5.88..20.16 rows=1 width=203) (actual time=0.514..1.863 rows=23 loops=1)
                                                               Buffers: shared hit=364
                                                               ->  Nested Loop  (cost=5.61..19.73 rows=1 width=187) (actual time=0.474..1.682 rows=23 loops=1)
                                                                     Buffers: shared hit=295
                                                                     ->  Nested Loop  (cost=5.33..18.82 rows=1 width=142) (actual time=0.424..1.446 rows=23 loops=1)
                                                                           Buffers: shared hit=226
                                                                           ->  Hash Join  (cost=4.91..10.44 rows=1 width=80) (actual time=0.340..1.148 rows=23 loops=1)
                                                                                 Hash Cond: (users.affiliate_id = acl_allowed_affiliate.affiliate_id)
                                                                                 Buffers: shared hit=134
                                                                                 ->  Index Scan using users_ix01 on users  (cost=0.43..5.45 rows=189 width=72) (actual time=0.090..0.822 rows=166 loops=1)
                                                                                       Index Cond: (((unique_identifier)::text ~>=~ 'robinson06'::text) AND ((unique_identifier)::text ~<~ 'robinson07'::text))
                                                                                       Filter: (((type)::text = ANY ('{LOCAL,EXTERNAL}'::text[])) AND ((unique_identifier)::text ~~ 'robinson06%'::text))
                                                                                       Buffers: shared hit=127
                                                                                 ->  Hash  (cost=4.45..4.45 rows=2 width=8) (actual time=0.135..0.136 rows=1 loops=1)
                                                                                       Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                                                                       Buffers: shared hit=4
                                                                                       ->  Index Only Scan using pk_acl_allowed_affiliate on acl_allowed_affiliate  (cost=0.41..4.45 rows=2 width=8) (actual time=0.115..0.117 rows=1 loops=1)
                                                                                             Index Cond: ((user_id = '1468137'::bigint) AND (permission = 'READ'::text))
                                                                                             Heap Fetches: 0
                                                                                             Buffers: shared hit=4
                                                                           ->  Index Scan using pk_user_profile on user_profile  (cost=0.43..8.38 rows=1 width=62) (actual time=0.011..0.011 rows=1 loops=23)
                                                                                 Index Cond: (user_id = users.user_id)
                                                                                 Buffers: shared hit=92
                                                                     ->  Index Scan using pk_user_realm on user_realm  (cost=0.27..0.91 rows=1 width=60) (actual time=0.008..0.008 rows=1 loops=23)
                                                                           Index Cond: ((user_realm_id)::text = (users.user_realm_id)::text)
                                                                           Filter: ((type)::text = ANY ('{ADMIN,HUB,PLAYER}'::text[]))
                                                                           Buffers: shared hit=69
                                                               ->  Index Scan using pk_organisation on organisation  (cost=0.27..0.43 rows=1 width=16) (actual time=0.006..0.006 rows=1 loops=23)
                                                                     Index Cond: ((organisation_id)::text = (user_realm.organisation_id)::text)
                                                                     Buffers: shared hit=69
                                                         ->  Index Only Scan using pk_acl_allowed_organisation on acl_allowed_organisation  (cost=0.29..1.38 rows=1 width=9) (actual time=0.007..0.007 rows=1 loops=23)
                                                               Index Cond: ((user_id = '1468137'::bigint) AND (organisation_id = (user_realm.organisation_id)::text) AND (permission = 'READ'::text))
                                                               Heap Fetches: 0
                                                               Buffers: shared hit=47
                                                   ->  Index Scan using pk_affiliate on affiliate  (cost=0.28..0.86 rows=1 width=21) (actual time=0.005..0.005 rows=1 loops=23)
                                                         Index Cond: (affiliate_id = users.affiliate_id)
                                                         Buffers: shared hit=69
                                             ->  Index Only Scan using pk_acl_allowed_user_realm_category on acl_allowed_user_realm_category  (cost=0.28..0.59 rows=1 width=9) (actual time=0.008..0.008 rows=1 loops=23)
                                                   Index Cond: ((user_id = '1468137'::bigint) AND (user_realm_category_id = (user_realm.user_realm_category_id)::text) AND (permission = 'READ'::text))
                                                   Heap Fetches: 0
                                                   Buffers: shared hit=47
                                       ->  Index Scan using pk_user_statistics on user_statistics  (cost=0.43..0.51 rows=1 width=16) (actual time=0.030..0.030 rows=1 loops=23)
                                             Index Cond: (user_id = user_profile.user_id)
                                             Buffers: shared hit=92 dirtied=1
                                 ->  Index Scan using pk_vip_level on vip_level  (cost=0.14..0.22 rows=1 width=20) (actual time=0.005..0.005 rows=1 loops=23)
                                       Index Cond: (vip_level_id = users.vip_level_id)
                                       Buffers: shared hit=46
                           ->  Index Scan using pk_vip_schema on vip_schema  (cost=0.13..0.63 rows=1 width=22) (actual time=0.005..0.005 rows=1 loops=23)
                                 Index Cond: ((vip_schema_id)::text = (vip_level.vip_schema_id)::text)
                                 Buffers: shared hit=46
                     ->  Index Scan using pk_user_realm_category on user_realm_category  (cost=0.13..0.18 rows=1 width=1032) (actual time=0.005..0.005 rows=1 loops=23)
                           Index Cond: ((user_realm_category_id)::text = (user_realm.user_realm_category_id)::text)
                           Buffers: shared hit=46
               ->  Index Scan using local_balance_account_unq01 on local_balance_account  (cost=0.29..6.45 rows=1 width=15) (actual time=0.020..0.020 rows=1 loops=23)
                     Index Cond: ((user_id = users.user_id) AND ((balance_category)::text = 'CASH'::text))
                     Filter: ((currency)::text = (users.real_base_currency)::text)
                     Buffers: shared hit=67
 Planning:
   Buffers: shared hit=859
 Planning Time: 50.833 ms
 Execution Time: 5.480 ms
(85 rows) 

On Fri, 9 Sept 2022 at 22:06, Maxim Boguk <maxim.boguk@xxxxxxxxx> wrote:

On Thu, Sep 8, 2022 at 1:18 PM Matheus Martin <matheus.martin@xxxxxxxxxxxxxx> wrote:

We do have JIT enabled `jit=on` with `jit_above_cost=100000`.

I am sorry but I don't quite understand what role JIT plays in this situation with `auto_explain`. Could you please elaborate on that?

In your log - time spent during the execution stage (where auto-exlain can help) but during the bind/planning stage (e.g. generation of plan).

So you have a problem not with slow query execution, but with slow query planning, so autoexplain cannot help in that case.

JIT is one possible explanation of planning stage slowdown.

Can you run explain (analyze, costs, buffers, timing) of your query?

And check how long the planning stage took and check if JIT was used or not (and how much time spent during JIT if it had been used).

--

Maxim Boguk
Senior Postgresql DBA
https://dataegret.com/

Phone UA: +380 99 143 0000
Phone AU: +61  45 218 5678