Subject: Problem with a Query

From: Siraj G <[email-masked]>
Date: Tue, 13 Aug 2024 09:33:50 +0530

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)

---

From: Tom Lane <[email-masked]>
Date: Tue, 13 Aug 2024 00:27:11 -0400

Siraj G <[email-masked]> writes:
> found that the SQL is using NESTED LOOP where the cost is too high.

>                            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