po 20. 12. 2021 v 17:50 odesÃlatel iulian dragos < iulian.dra...@databricks.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.steh...@gmail.com> > wrote: > >> Hi >> >> po 20. 12. 2021 v 13:31 odesÃlatel iulian dragos < >> iulian.dra...@databricks.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) >>> >>
