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

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)
>