Thread: Problem with a Query

Problem with a Query

From

Siraj G

Date:

13 August, 07:03:50

Hello!

We migrated a PgSQL database from Cloud SQL to compute engine and since then there is a SQL we observed taking a long time. After some study, I found that the SQL is using NESTED LOOP where the cost is too high. I tried VACUUM FULL and ANALYZE, but to no avail. Only when I disabled the nested loop (enable_nestloop) the query starts running normally.

I checked in the cloud SQL the nested loop is enabled, not sure why this difference. Can anyone please assist.

Here is the execution plan (bad one):

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=120339.76..132772.17 rows=1 width=775) (actual time=901159.223..901897.801 rows=12 loops=1)
Join Filter: (marketing_app_homecounsellinglead.id = w0.cancel_event_id)
Rows Removed by Join Filter: 28926
Buffers: shared hit=502303510 read=299 dirtied=1
-> Unique (cost=1.58..4283.42 rows=1 width=4) (actual time=47.768..51.917 rows=13 loops=1)
Buffers: shared hit=9680 read=19
-> Nested Loop Semi Join (cost=1.58..4283.42 rows=1 width=4) (actual time=47.767..51.900 rows=36 loops=1)
Buffers: shared hit=9680 read=19
-> Nested Loop (cost=1.00..4282.75 rows=1 width=8) (actual time=46.703..51.596 rows=44 loops=1)
Buffers: shared hit=9379 read=19
-> Index Scan using marketing_a_cancel__55ffff_idx on marketing_app_leadhistory w0 (cost=0.57..4274.30 rows=1 width=8) (actual time=46.678..51.232 rows=44 loops=1)
Index Cond: ((cancel_event_id IS NOT NULL) AND (cancel_event_type = 1))
Filter: ((status_id = 93) AND ((followup_date)::date >= '2024-08-01'::date) AND ((followup_date)::date <= '2024-08-07'::date))
Rows Removed by Filter: 22268
Buffers: shared hit=9170 read=19
-> Index Scan using marketing_app_leadinfo_pkey on marketing_app_leadinfo w1 (cost=0.43..8.45 rows=1 width=8) (actual time=0.006..0.006 rows=1 loops=44)
Index Cond: (id = w0.lead_id)
Buffers: shared hit=209
-> Nested Loop Semi Join (cost=0.58..0.66 rows=1 width=12) (actual time=0.006..0.006 rows=1 loops=44)
Join Filter: (v0_1.id = u0_2.id)
Buffers: shared hit=301
-> Index Only Scan using branch_id_idx on branch v0_1 (cost=0.14..0.16 rows=1 width=4) (actual time=0.001..0.002 rows=1 loops=44)
Index Cond: (id = w1.branch_id)
Heap Fetches: 44
Buffers: shared hit=88
-> Nested Loop (cost=0.43..0.49 rows=1 width=8) (actual time=0.004..0.004 rows=1 loops=44)
Join Filter: (u0_2.id = u1_2.branch_id)
Buffers: shared hit=213
-> Index Only Scan using branch_id_idx on branch u0_2 (cost=0.14..0.16 rows=1 width=4) (actual time=0.001..0.001 rows=1 loops=44)
Index Cond: (id = w1.branch_id)
Heap Fetches: 44
Buffers: shared hit=88
-> Index Only Scan using "Employee_brancanh_employee_id_branch_id_06fcf064_uniq" on authentication_employee_branch u1_2 (cost=0.29..0.31 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=44)
Index Cond: ((employee_id = 43) AND (branch_id = w1.branch_id))
Heap Fetches: 36
Buffers: shared hit=125
-> Hash Join (cost=120338.17..128483.90 rows=387 width=775) (actual time=69312.677..69372.647 rows=2226 loops=13)
Hash Cond: (marketing_app_homecounsellinglead.lead_id = marketing_app_leadinfo.id)
Buffers: shared hit=502293830 read=280 dirtied=1
-> Seq Scan on marketing_app_homecounsellinglead (cost=0.00..7513.53 rows=167553 width=775) (actual time=0.003..19.903 rows=167589 loops=13)
Buffers: shared hit=75894
-> Hash (cost=119938.59..119938.59 rows=31967 width=4) (actual time=901063.121..901063.129 rows=5138545 loops=1)
Buckets: 8388608 (originally 32768) Batches: 1 (originally 1) Memory Usage: 246188kB
Buffers: shared hit=502217936 read=280 dirtied=1
-> Nested Loop (cost=56.29..119938.59 rows=31967 width=4) (actual time=0.271..899599.420 rows=5138545 loops=1)
Join Filter: (u0.id = marketing_app_leadinfo.branch_id)
Rows Removed by Join Filter: 713188839
Buffers: shared hit=502217936 read=280 dirtied=1
-> Nested Loop (cost=55.85..1005.32 rows=20 width=16) (actual time=0.237..35.473 rows=75208 loops=1)
Buffers: shared hit=272
-> Nested Loop Semi Join (cost=14.63..122.14 rows=20 width=4) (actual time=0.034..1.153 rows=553 loops=1)
Join Filter: (marketing_app_contactsource.field_type_id = u0_1.id)
Rows Removed by Join Filter: 1090
Buffers: shared hit=194
-> Index Scan using marketing_app_contactsource_pkey on marketing_app_contactsource (cost=0.28..54.74 rows=550 width=8) (actual time=0.006..0.460 rows=553
loops=1)
Buffers: shared hit=189
-> Materialize (cost=14.36..26.16 rows=5 width=8) (actual time=0.000..0.000 rows=3 loops=553)
Buffers: shared hit=5
-> Hash Join (cost=14.36..26.14 rows=5 width=8) (actual time=0.023..0.032 rows=10 loops=1)
Hash Cond: (u0_1.id = u1_1.fieldtype_id)
Buffers: shared hit=5
-> Seq Scan on authentication_fieldtype u0_1 (cost=0.00..11.40 rows=140 width=4) (actual time=0.004..0.006 rows=10 loops=1)
Buffers: shared hit=1
-> Hash (cost=14.29..14.29 rows=5 width=4) (actual time=0.014..0.015 rows=10 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 9kB
Buffers: shared hit=4
-> Index Only Scan using authentication_employee__employee_id_fieldtype_id_a490d886_uniq on authentication_employee_field_type u1_1 (cost
=0.29..14.29 rows=5 width=4) (actual time=0.009..0.012 rows=10 loops=1)
Index Cond: (employee_id = 43)
Heap Fetches: 10
Buffers: shared hit=4
-> HashAggregate (cost=41.22..42.69 rows=147 width=12) (actual time=0.001..0.042 rows=136 loops=553)
Group Key: v0.id
Batches: 1 Memory Usage: 40kB
Buffers: shared hit=78
-> Hash Semi Join (cost=29.97..40.85 rows=147 width=12) (actual time=0.136..0.176 rows=136 loops=1)
Hash Cond: (v0.id = u0.id)
Buffers: shared hit=78
-> Seq Scan on branch v0 (cost=0.00..8.78 rows=178 width=4) (actual time=0.003..0.015 rows=178 loops=1)
Buffers: shared hit=7
-> Hash (cost=28.13..28.13 rows=147 width=8) (actual time=0.129..0.132 rows=136 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 14kB
Buffers: shared hit=71
-> Hash Join (cost=18.87..28.13 rows=147 width=8) (actual time=0.069..0.118 rows=136 loops=1)
Hash Cond: (u0.id = u1.branch_id)
Buffers: shared hit=71
-> Seq Scan on branch u0 (cost=0.00..8.78 rows=178 width=4) (actual time=0.002..0.026 rows=178 loops=1)
Buffers: shared hit=7
-> Hash (cost=17.03..17.03 rows=147 width=4) (actual time=0.063..0.064 rows=136 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 13kB
Buffers: shared hit=64
-> Index Only Scan using "Employee_brancanh_employee_id_branch_id_06fcf064_uniq" on authentication_employee_branch u1 (cost=0.29..1
7.03 rows=147 width=4) (actual time=0.008..0.050 rows=136 loops=1)
Index Cond: (employee_id = 43)
Heap Fetches: 122
Buffers: shared hit=64
-> Index Scan using marketing_app_leadinfo_contact_source_id_b9ffb703 on marketing_app_leadinfo (cost=0.43..5632.63 rows=25123 width=12) (actual time=0.354..10.980 row
s=9551 loops=75208)
Index Cond: (contact_source_id = marketing_app_contactsource.id)
Filter: ((academic_year)::text = '2024-25'::text)
Rows Removed by Filter: 15269
Buffers: shared hit=502217664 read=280 dirtied=1
Planning:
Buffers: shared hit=163
Planning Time: 2.082 ms
JIT:
Functions: 84
Options: Inlining false, Optimization false, Expressions true, Deforming true
Timing: Generation 5.327 ms, Inlining 0.000 ms, Optimization 1.802 ms, Emission 37.293 ms, Total 44.422 ms
Execution Time: 901926.050 ms
(107 rows)

Re: Problem with a Query

From

Tom Lane

Date:

13 August, 07:27:11

Siraj G <tosiraj.g@gmail.com> writes:
> We migrated a PgSQL database from Cloud SQL to compute engine and since
> then there is a SQL we observed taking a long time. After some study, I
> found that the SQL is using NESTED LOOP where the cost is too high.

The core of your problem seems to be here:

>                      ->  Index Scan using marketing_a_cancel__55ffff_idx on
> marketing_app_leadhistory w0  (cost=0.57..4274.30 rows=1 width=8) (actual
> time=46.678..51.232 rows=44 loops=1)
>                            Index Cond: ((cancel_event_id IS NOT NULL) AND
> (cancel_event_type = 1))
>                            Filter: ((status_id = 93) AND
> ((followup_date)::date >= '2024-08-01'::date) AND ((followup_date)::date <=
> '2024-08-07'::date))
>                            Rows Removed by Filter: 22268
>                            Buffers: shared hit=9170 read=19

If the planner had estimated 40-some rows out of this step, rather
than one, it would certainly not have chosen to use nestloop joins
atop this.  So the big problem to focus on is making that estimate
better.

A secondary problem is that the choice of index seems poor: the
index itself is selecting 44+22268 = 22312 rows and then the filter
condition is throwing away 99.8% of those rows.  Probably, using
an index on (status_id, followup_date) would have worked better.

I suspect that both of these things are tied to the non-normalization
of your "cancel" condition.  The planner probably believes that
"cancel_event_id IS NOT NULL" is statistically independent of
"cancel_event_type = 1"; but I'll bet it isn't, and thus the index
condition selects many more rows than the planner guessed.  You might
be able to improve that estimate by creating extended stats on both of
those columns, but really a better idea would be to take a step back
and figure out if those two columns can't be merged into one.

            regards, tom lane

Re: Problem with a Query

From

Siraj G

Date:

26 August, 16:29:57

Thanks Tom. Collecting full stats on the tables involved corrected the execution.

On Tue, Aug 13, 2024 at 9:57 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Siraj G <tosiraj.g@gmail.com> writes:
> We migrated a PgSQL database from Cloud SQL to compute engine and since
> then there is a SQL we observed taking a long time. After some study, I
> found that the SQL is using NESTED LOOP where the cost is too high.

The core of your problem seems to be here:

> -> Index Scan using marketing_a_cancel__55ffff_idx on
> marketing_app_leadhistory w0 (cost=0.57..4274.30 rows=1 width=8) (actual
> time=46.678..51.232 rows=44 loops=1)
> Index Cond: ((cancel_event_id IS NOT NULL) AND
> (cancel_event_type = 1))
> Filter: ((status_id = 93) AND
> ((followup_date)::date >= '2024-08-01'::date) AND ((followup_date)::date <=
> '2024-08-07'::date))
> Rows Removed by Filter: 22268
> Buffers: shared hit=9170 read=19

If the planner had estimated 40-some rows out of this step, rather
than one, it would certainly not have chosen to use nestloop joins
atop this. So the big problem to focus on is making that estimate
better.

A secondary problem is that the choice of index seems poor: the
index itself is selecting 44+22268 = 22312 rows and then the filter
condition is throwing away 99.8% of those rows. Probably, using
an index on (status_id, followup_date) would have worked better.

I suspect that both of these things are tied to the non-normalization
of your "cancel" condition. The planner probably believes that
"cancel_event_id IS NOT NULL" is statistically independent of
"cancel_event_type = 1"; but I'll bet it isn't, and thus the index
condition selects many more rows than the planner guessed. You might
be able to improve that estimate by creating extended stats on both of
those columns, but really a better idea would be to take a step back
and figure out if those two columns can't be merged into one.

regards, tom lane

Re: Problem with a Query

From

Ron Johnson

Date:

26 August, 19:22:11

Aggressive autoanalyze and autovacuum settings solve most query problems. These are my settings:

default_statistics_target = 5000

autovacuum_vacuum_scale_factor = 0.015
autovacuum_vacuum_threshold = 250
autovacuum_analyze_scale_factor = 0.015
autovacuum_analyze_threshold = 250

Such a high default_statistics_target value is controversial, but works for our databases, and resetting it to 100 doesn't noticably speed up slow parse/optimize on queries that take a long time to parse/optimize any more than the 5000 value.

On Mon, Aug 26, 2024 at 6:30 AM Siraj G <tosiraj.g@gmail.com> wrote:

Thanks Tom. Collecting full stats on the tables involved corrected the execution.

On Tue, Aug 13, 2024 at 9:57 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
Siraj G <tosiraj.g@gmail.com> writes:
> We migrated a PgSQL database from Cloud SQL to compute engine and since
> then there is a SQL we observed taking a long time. After some study, I
> found that the SQL is using NESTED LOOP where the cost is too high.

The core of your problem seems to be here:

> -> Index Scan using marketing_a_cancel__55ffff_idx on
> marketing_app_leadhistory w0 (cost=0.57..4274.30 rows=1 width=8) (actual
> time=46.678..51.232 rows=44 loops=1)
> Index Cond: ((cancel_event_id IS NOT NULL) AND
> (cancel_event_type = 1))
> Filter: ((status_id = 93) AND
> ((followup_date)::date >= '2024-08-01'::date) AND ((followup_date)::date <=
> '2024-08-07'::date))
> Rows Removed by Filter: 22268
> Buffers: shared hit=9170 read=19

If the planner had estimated 40-some rows out of this step, rather
than one, it would certainly not have chosen to use nestloop joins
atop this. So the big problem to focus on is making that estimate
better.

A secondary problem is that the choice of index seems poor: the
index itself is selecting 44+22268 = 22312 rows and then the filter
condition is throwing away 99.8% of those rows. Probably, using
an index on (status_id, followup_date) would have worked better.

I suspect that both of these things are tied to the non-normalization
of your "cancel" condition. The planner probably believes that
"cancel_event_id IS NOT NULL" is statistically independent of
"cancel_event_type = 1"; but I'll bet it isn't, and thus the index
condition selects many more rows than the planner guessed. You might
be able to improve that estimate by creating extended stats on both of
those columns, but really a better idea would be to take a step back
and figure out if those two columns can't be merged into one.

regards, tom lane

Death to America, and butter sauce.

Iraq lobster!