Re: Missing query plan for auto_explain.

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(dot)boguk(at)gmail(dot)com> wrote:

>
>
> On Thu, Sep 8, 2022 at 1:18 PM Matheus Martin <
> matheus(dot)martin(at)voidbridge(dot)com> 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
>
>