Re: How to reduce query planning time (10s)

po 20. 12. 2021 v 17:50 odesílatel iulian dragos <
iulian(dot)dragos(at)databricks(dot)com> napsal:

> Thanks for the suggestion!
>
> Reading through the docs it looks like this might involve some downtime
> (locking writes to the tables whos indexes are being rebuilt) and this is a
> running system. I may need some time to setup a database copy and try to
> reproduce the issue (dev deployment doesn't exhibit the performance
> problem, so it must be related to table contents).
>
> Is there any way to validate the bloated index hypothesis before I invest
> too much in this direction?
>

https://wiki.postgresql.org/wiki/Show_database_bloat

Pavel

>
> iulian
>
>
> On Mon, Dec 20, 2021 at 1:42 PM Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
> wrote:
>
>> Hi
>>
>> po 20. 12. 2021 v 13:31 odesílatel iulian dragos <
>> iulian(dot)dragos(at)databricks(dot)com> napsal:
>>
>>> Hi,
>>>
>>> I was analyzing the query performance in a certain code path and noticed
>>> that practically all of the query time is spent planning (11s planning,
>>> 200ms execution time). Here is the output of EXPLAIN ANALYZE. I tried using
>>> a prepared statement with three parameters (run_id, and the two text
>>> comparisons) and the performance is similar, even when run multiple times
>>> with the same parameters. Could someone give me some hints on how to speed
>>> this query up?
>>>
>>> explain analyze SELECT x13.run_id, x19.text, x13.id, x17.status
>>>
>>> FROM module_result x13
>>>
>>> INNER JOIN result_name x14 ON x13.name_id = x14.id
>>>
>>> INNER JOIN test_result x17 ON x13.id = x17.module_result_id
>>>
>>> INNER JOIN result_name x19 ON x17.name_id = x19.id
>>>
>>> WHERE x19.text IN ('devtools/devbox/devbox_test_scalastyle') AND x13.run_id
>>> IN (3769263) AND x14.text = 'Lint-Pr'
>>>
>>>
>>> +--------------------------------------------------------------------------------------------------------------------------------------------------+
>>>
>>> | QUERY PLAN
>>>
>>> |
>>>
>>>
>>> |--------------------------------------------------------------------------------------------------------------------------------------------------|
>>>
>>> | Nested Loop (cost=993.29..160107.01 rows=1 width=557) (actual
>>> time=0.147..0.148 rows=0 loops=1)
>>> |
>>>
>>> | Join Filter: (x13.id = x17.module_result_id)
>>>
>>> |
>>>
>>> | -> Nested Loop (cost=2.27..18.32 rows=1 width=12) (actual
>>> time=0.147..0.147 rows=0 loops=1)
>>> |
>>>
>>> | -> Index Scan using result_name_text_key on result_name x14 (cost=1.69..9.71
>>> rows=1 width=8) (actual time=0.146..0.147 rows=0 loops=1) |
>>>
>>> | Index Cond: (text = 'Lint-Pr'::text)
>>>
>>> |
>>>
>>> | -> Index Scan using module_result_run_id_name_id_idx on
>>> module_result x13 (cost=0.57..8.59 rows=1 width=20) (never executed)
>>> |
>>>
>>> | Index Cond: ((run_id = 3769263) AND (name_id = x14.id))
>>>
>>> |
>>>
>>> | -> Nested Loop (cost=991.02..160087.73 rows=77 width=553) (never
>>> executed)
>>> |
>>>
>>> | -> Index Scan using result_name_text_key on result_name x19 (cost=1.69..9.71
>>> rows=1 width=549) (never executed) |
>>>
>>> | Index Cond: (text =
>>> 'devtools/devbox/devbox_test_scalastyle'::text)
>>> |
>>>
>>> | -> Bitmap Heap Scan on test_result x17 (cost=989.33..159674.48
>>> rows=40354 width=20) (never executed)
>>> |
>>>
>>> | Recheck Cond: (name_id = x19.id)
>>>
>>> |
>>>
>>> | -> Bitmap Index Scan on test_result_name_id_idx (cost=0.00..979.24
>>> rows=40354 width=0) (never executed) |
>>>
>>> | Index Cond: (name_id = x19.id)
>>>
>>> |
>>>
>>> | Planning Time: 11257.713 ms
>>>
>>> |
>>>
>>> | Execution Time: 0.204 ms
>>>
>>> |
>>>
>>>
>>> +--------------------------------------------------------------------------------------------------------------------------------------------------+
>>>
>>> EXPLAIN
>>>
>>> Time: 11.505s (11 seconds), executed in: 11.496s (11 seconds)
>>>
>>>
>>>
>>> explain analyze execute test_history_prep2(3769263, 'Lint-Pr',
>>> 'devtools/devbox/devbox_test_scalastyle')
>>>
>>>
>>> +--------------------------------------------------------------------------------------------------------------------------------------------------+
>>>
>>> | QUERY PLAN
>>>
>>> |
>>>
>>>
>>> |--------------------------------------------------------------------------------------------------------------------------------------------------|
>>>
>>> | Nested Loop (cost=993.30..160114.89 rows=1 width=557) (actual
>>> time=0.173..0.173 rows=0 loops=1)
>>> |
>>>
>>> | Join Filter: (x13.id = x17.module_result_id)
>>>
>>> |
>>>
>>> | -> Nested Loop (cost=2.27..18.32 rows=1 width=12) (actual
>>> time=0.172..0.173 rows=0 loops=1)
>>> |
>>>
>>> | -> Index Scan using result_name_text_key on result_name x14 (cost=1.69..9.71
>>> rows=1 width=8) (actual time=0.172..0.172 rows=0 loops=1) |
>>>
>>> | Index Cond: (text = 'Lint-Pr'::text)
>>>
>>> |
>>>
>>> | -> Index Scan using module_result_run_id_name_id_idx on
>>> module_result x13 (cost=0.57..8.59 rows=1 width=20) (never executed)
>>> |
>>>
>>> | Index Cond: ((run_id = 3769263) AND (name_id = x14.id))
>>>
>>> |
>>>
>>> | -> Nested Loop (cost=991.03..160095.61 rows=77 width=553) (never
>>> executed)
>>> |
>>>
>>> | -> Index Scan using result_name_text_key on result_name x19 (cost=1.69..9.71
>>> rows=1 width=549) (never executed) |
>>>
>>> | Index Cond: (text =
>>> 'devtools/devbox/devbox_test_scalastyle'::text)
>>> |
>>>
>>> | -> Bitmap Heap Scan on test_result x17 (cost=989.34..159682.34
>>> rows=40356 width=20) (never executed)
>>> |
>>>
>>> | Recheck Cond: (name_id = x19.id)
>>>
>>> |
>>>
>>> | -> Bitmap Index Scan on test_result_name_id_idx (cost=0.00..979.25
>>> rows=40356 width=0) (never executed) |
>>>
>>> | Index Cond: (name_id = x19.id)
>>>
>>> |
>>>
>>> | Planning Time: 11074.634 ms
>>>
>>> |
>>>
>>> | Execution Time: 0.224 ms
>>>
>>> |
>>>
>>>
>>> +--------------------------------------------------------------------------------------------------------------------------------------------------+
>>>
>>> EXPLAIN
>>>
>>>
>> Can you try reindex the indexes on related tables. The bloated index is a
>> common source of slow query planning.
>>
>> Regards
>>
>> Pavel
>>
>>
>>
>>> Time: 11.425s (11 seconds), executed in: 11.417s (11 seconds)
>>>
>>