How to reduce query planning time (10s)

Started by iulian dragosover 4 years ago5 messagesgeneral

iulian.dragos@databricks.com

over 4 years ago

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

Time: 11.425s (11 seconds), executed in: 11.417s (11 seconds)

Pavel Stehule

pavel.stehule@gmail.com

over 4 years ago

In reply to: iulian dragos (#1)

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

po 20. 12. 2021 v 13:31 odesílatel iulian dragos <
iulian.dragos@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

Show quoted text

Time: 11.425s (11 seconds), executed in: 11.417s (11 seconds)

iulian dragos

iulian.dragos@databricks.com

over 4 years ago

In reply to: Pavel Stehule (#2)

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

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?

iulian

On Mon, Dec 20, 2021 at 1:42 PM Pavel Stehule <pavel.stehule@gmail.com>
wrote:

Show quoted text

Hi

po 20. 12. 2021 v 13:31 odesílatel iulian dragos <
iulian.dragos@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)

Pavel Stehule

pavel.stehule@gmail.com

over 4 years ago

In reply to: iulian dragos (#3)

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

po 20. 12. 2021 v 17:50 odesílatel iulian dragos <
iulian.dragos@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

Show quoted text

iulian

On Mon, Dec 20, 2021 at 1:42 PM Pavel Stehule <pavel.stehule@gmail.com>
wrote:

Hi

po 20. 12. 2021 v 13:31 odesílatel iulian dragos <
iulian.dragos@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)

Tom Lane

tgl@sss.pgh.pa.us

over 4 years ago

In reply to: iulian dragos (#3)

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

iulian dragos <iulian.dragos@databricks.com> writes:

Is there any way to validate the bloated index hypothesis before I invest
too much in this direction?

A plain old VACUUM ought to take care of most of the problem.

regards, tom lane