Hello,
I've noticed that we our queries have very bad estimates, which leads to the planner using slow nested loops, here is a subset of the query without tenant separation (correct estimates):
explain (ANALYZE, COSTS, BUFFERS, FORMAT text)
select *
from "Reservation"."Reservation" r
join "Rates"."TimeSliceDefinition" t on r."TimeSliceDefinitionId" = t."Id"
join "Reservation"."NoShowFee" f on r."NoShowFeeId" = f."Id"
where r."DepartureUtc" > '2018-01-01' and r."ArrivalUtc" < '2018-09-30'
Gather (cost=14034.74..22788.40 rows=12346 width=793) (actual time=23.815..57.178 rows=12263 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=18997
-> Hash Join (cost=13034.74..20553.80 rows=5144 width=793) (actual time=20.869..49.029 rows=4088 loops=3)
Hash Cond: (r."TimeSliceDefinitionId" = t."Id")
Buffers: shared hit=18997
-> Parallel Hash Join (cost=12907.55..20413.09 rows=5144 width=662) (actual time=19.210..45.177 rows=4088 loops=3)
Hash Cond: (f."Id" = r."NoShowFeeId")
Buffers: shared hit=18683
-> Parallel Seq Scan on "NoShowFee" f (cost=0.00..7343.25 rows=61825 width=143) (actual time=0.006..15.481 rows=49460 loops=3)
Buffers: shared hit=6725
-> Parallel Hash (cost=12843.25..12843.25 rows=5144 width=519) (actual time=19.071..19.072 rows=4088 loops=3)
Buckets: 16384 Batches: 1 Memory Usage: 4832kB
Buffers: shared hit=11958
-> Parallel Seq Scan on "Reservation" r (cost=0.00..12843.25 rows=5144 width=519) (actual time=0.971..14.919 rows=4088 loops=3)
Filter: (("DepartureUtc" > '2018-01-01 00:00:00'::timestamp without time zone) AND ("ArrivalUtc" < '2018-09-30 00:00:00'::timestamp without time zone))
Rows Removed by Filter: 43126
Buffers: shared hit=11958
-> Hash (cost=96.53..96.53 rows=2453 width=131) (actual time=1.586..1.586 rows=2453 loops=3)
Buckets: 4096 Batches: 1 Memory Usage: 457kB
Buffers: shared hit=216
-> Seq Scan on "TimeSliceDefinition" t (cost=0.00..96.53 rows=2453 width=131) (actual time=0.009..0.697 rows=2453 loops=3)
Buffers: shared hit=216
Planning Time: 0.424 ms
Execution Time: 58.146 ms
select *
from "Reservation"."Reservation" r
join "Rates"."TimeSliceDefinition" t on r."TimeSliceDefinitionId" = t."Id"
join "Reservation"."NoShowFee" f on r."NoShowFeeId" = f."Id"
where r."DepartureUtc" > '2018-01-01' and r."ArrivalUtc" < '2018-09-30'
Gather (cost=14034.74..22788.40 rows=12346 width=793) (actual time=23.815..57.178 rows=12263 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=18997
-> Hash Join (cost=13034.74..20553.80 rows=5144 width=793) (actual time=20.869..49.029 rows=4088 loops=3)
Hash Cond: (r."TimeSliceDefinitionId" = t."Id")
Buffers: shared hit=18997
-> Parallel Hash Join (cost=12907.55..20413.09 rows=5144 width=662) (actual time=19.210..45.177 rows=4088 loops=3)
Hash Cond: (f."Id" = r."NoShowFeeId")
Buffers: shared hit=18683
-> Parallel Seq Scan on "NoShowFee" f (cost=0.00..7343.25 rows=61825 width=143) (actual time=0.006..15.481 rows=49460 loops=3)
Buffers: shared hit=6725
-> Parallel Hash (cost=12843.25..12843.25 rows=5144 width=519) (actual time=19.071..19.072 rows=4088 loops=3)
Buckets: 16384 Batches: 1 Memory Usage: 4832kB
Buffers: shared hit=11958
-> Parallel Seq Scan on "Reservation" r (cost=0.00..12843.25 rows=5144 width=519) (actual time=0.971..14.919 rows=4088 loops=3)
Filter: (("DepartureUtc" > '2018-01-01 00:00:00'::timestamp without time zone) AND ("ArrivalUtc" < '2018-09-30 00:00:00'::timestamp without time zone))
Rows Removed by Filter: 43126
Buffers: shared hit=11958
-> Hash (cost=96.53..96.53 rows=2453 width=131) (actual time=1.586..1.586 rows=2453 loops=3)
Buckets: 4096 Batches: 1 Memory Usage: 457kB
Buffers: shared hit=216
-> Seq Scan on "TimeSliceDefinition" t (cost=0.00..96.53 rows=2453 width=131) (actual time=0.009..0.697 rows=2453 loops=3)
Buffers: shared hit=216
Planning Time: 0.424 ms
Execution Time: 58.146 ms
and with tenant separation (wrong estimates):
explain (ANALYZE, COSTS, BUFFERS, FORMAT text)
select *
from "Reservation"."Reservation" r
join "Rates"."TimeSliceDefinition" t on r."TimeSliceDefinitionId" = t."Id"
join "Reservation"."NoShowFee" f on r."NoShowFeeId" = f."Id"
where r."DepartureUtc" > '2018-01-01' and r."ArrivalUtc" < '2019-12-31' and r."AccountCode" = 'Code1' and t."AccountCode" = 'Code1' and f."AccountCode" = 'Code1'
Nested Loop (cost=419.37..6656.11 rows=3 width=793) (actual time=1.367..95.051 rows=8992 loops=1)
Buffers: shared hit=41970
-> Nested Loop (cost=418.95..6504.77 rows=49 width=650) (actual time=1.355..49.789 rows=8992 loops=1)
Buffers: shared hit=5980
-> Bitmap Heap Scan on "TimeSliceDefinition" t (cost=4.39..39.99 rows=14 width=131) (actual time=0.015..0.035 rows=14 loops=1)
Recheck Cond: ("AccountCode" = 'Code1'::text)
Heap Blocks: exact=7
Buffers: shared hit=9
-> Bitmap Index Scan on "IX_TimeSliceDefinition_AccountCode_PropertyId_Name" (cost=0.00..4.39 rows=14 width=0) (actual time=0.010..0.010 rows=14 loops=1)
Index Cond: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=2
-> Bitmap Heap Scan on "Reservation" r (cost=414.56..461.66 rows=11 width=519) (actual time=1.104..2.987 rows=642 loops=14)
Recheck Cond: (("TimeSliceDefinitionId" = t."Id") AND ("AccountCode" = 'Code1'::text))
Filter: (("DepartureUtc" > '2018-01-01 00:00:00'::timestamp without time zone) AND ("ArrivalUtc" < '2019-12-31 00:00:00'::timestamp without time zone))
Rows Removed by Filter: 14
Heap Blocks: exact=4776
Buffers: shared hit=5971
-> BitmapAnd (cost=414.56..414.56 rows=12 width=0) (actual time=1.057..1.057 rows=0 loops=14)
Buffers: shared hit=1195
-> Bitmap Index Scan on "IX_Reservation_TimeSliceDefinitionId" (cost=0.00..13.84 rows=189 width=0) (actual time=0.063..0.063 rows=665 loops=14)
Index Cond: ("TimeSliceDefinitionId" = t."Id")
Buffers: shared hit=90
-> Bitmap Index Scan on "IX_Reservation_AccountCode_EntityId" (cost=0.00..398.31 rows=8786 width=0) (actual time=1.056..1.056 rows=9225 loops=13)
Index Cond: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=1105
-> Index Scan using "PK_NoShowFee" on "NoShowFee" f (cost=0.42..3.09 rows=1 width=143) (actual time=0.003..0.003 rows=1 loops=8992)
Index Cond: ("Id" = r."NoShowFeeId")
Filter: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=35990
Planning Time: 0.766 ms
Execution Time: 95.687 ms
select *
from "Reservation"."Reservation" r
join "Rates"."TimeSliceDefinition" t on r."TimeSliceDefinitionId" = t."Id"
join "Reservation"."NoShowFee" f on r."NoShowFeeId" = f."Id"
where r."DepartureUtc" > '2018-01-01' and r."ArrivalUtc" < '2019-12-31' and r."AccountCode" = 'Code1' and t."AccountCode" = 'Code1' and f."AccountCode" = 'Code1'
Nested Loop (cost=419.37..6656.11 rows=3 width=793) (actual time=1.367..95.051 rows=8992 loops=1)
Buffers: shared hit=41970
-> Nested Loop (cost=418.95..6504.77 rows=49 width=650) (actual time=1.355..49.789 rows=8992 loops=1)
Buffers: shared hit=5980
-> Bitmap Heap Scan on "TimeSliceDefinition" t (cost=4.39..39.99 rows=14 width=131) (actual time=0.015..0.035 rows=14 loops=1)
Recheck Cond: ("AccountCode" = 'Code1'::text)
Heap Blocks: exact=7
Buffers: shared hit=9
-> Bitmap Index Scan on "IX_TimeSliceDefinition_AccountCode_PropertyId_Name" (cost=0.00..4.39 rows=14 width=0) (actual time=0.010..0.010 rows=14 loops=1)
Index Cond: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=2
-> Bitmap Heap Scan on "Reservation" r (cost=414.56..461.66 rows=11 width=519) (actual time=1.104..2.987 rows=642 loops=14)
Recheck Cond: (("TimeSliceDefinitionId" = t."Id") AND ("AccountCode" = 'Code1'::text))
Filter: (("DepartureUtc" > '2018-01-01 00:00:00'::timestamp without time zone) AND ("ArrivalUtc" < '2019-12-31 00:00:00'::timestamp without time zone))
Rows Removed by Filter: 14
Heap Blocks: exact=4776
Buffers: shared hit=5971
-> BitmapAnd (cost=414.56..414.56 rows=12 width=0) (actual time=1.057..1.057 rows=0 loops=14)
Buffers: shared hit=1195
-> Bitmap Index Scan on "IX_Reservation_TimeSliceDefinitionId" (cost=0.00..13.84 rows=189 width=0) (actual time=0.063..0.063 rows=665 loops=14)
Index Cond: ("TimeSliceDefinitionId" = t."Id")
Buffers: shared hit=90
-> Bitmap Index Scan on "IX_Reservation_AccountCode_EntityId" (cost=0.00..398.31 rows=8786 width=0) (actual time=1.056..1.056 rows=9225 loops=13)
Index Cond: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=1105
-> Index Scan using "PK_NoShowFee" on "NoShowFee" f (cost=0.42..3.09 rows=1 width=143) (actual time=0.003..0.003 rows=1 loops=8992)
Index Cond: ("Id" = r."NoShowFeeId")
Filter: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=35990
Planning Time: 0.766 ms
Execution Time: 95.687 ms
now, these 2 queries are fairly similar in execution time. The problem is, that this is the kinda a base query and our ORM is building a monster query around it which takes 2-3 minutes to execute (for one specific tenant - not for others). I took the advise from https://www.postgresql.org/message-id/CAFh58O_Myr6G3tcH3gcGrF-=OExB08PJdWZcSBcEcovaiPsrHA@xxxxxxxxxxxxxx and tried the same query with SET enable_nestloop=OFF - it took 200ms when it used HASH JOINs
How can I improve the estimates? Just as a catch all, I tried to set default_statistics_target to 10000, re-analyzed the DB and it didn't help. I tried to to create ndistinct statistics to include the account code in the statistics:
CREATE STATISTICS MT_ReservationDepartureUtc (ndistinct) on "AccountCode", "DepartureUtc" from "Reservation"."Reservation";
CREATE STATISTICS MT_ReservationArrivalUtc (ndistinct) on "AccountCode", "ArrivalUtc" from "Reservation"."Reservation";
CREATE STATISTICS MT_ReservationNoShowFeeId (ndistinct) on "AccountCode", "NoShowFeeId" from "Reservation"."Reservation";
CREATE STATISTICS MT_ReservationTimeSliceDefinitionId (ndistinct) on "AccountCode", "TimeSliceDefinitionId" from "Reservation"."Reservation";
CREATE STATISTICS MT_ReservationArrivalUtc (ndistinct) on "AccountCode", "ArrivalUtc" from "Reservation"."Reservation";
CREATE STATISTICS MT_ReservationNoShowFeeId (ndistinct) on "AccountCode", "NoShowFeeId" from "Reservation"."Reservation";
CREATE STATISTICS MT_ReservationTimeSliceDefinitionId (ndistinct) on "AccountCode", "TimeSliceDefinitionId" from "Reservation"."Reservation";
but that didn't help either
So I know the issue - it's using a nested loop instead of a hash join, for that one account which has a ton of data sets - all others have less items, that's why they are fine, although even other accounts would benefit from hash joins - one test had 0,15ms execution time instead of 95,5ms
How can I help postgres to collect the correct data?
Thank you,
Peter