Bad Estimate for multi tenant database queries

From: Peter Grman <peter(dot)grman(at)gmail(dot)com>
To: pgsql-general(at)lists(dot)postgresql(dot)org
Subject: Bad Estimate for multi tenant database queries
Date: 2019-08-29 20:54:04
Message-ID: CACF7Wx36G0YBM7xjDhZkG1d_B8jgD6Q=WFCrk7o=exNiniom1g@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

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

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

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@mail.gmail.com
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";

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

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Adrian Klaver 2019-08-29 22:29:51 Re: How to log 'user time' in postgres logs
Previous Message Adrian Klaver 2019-08-29 19:19:10 Re: How to log 'user time' in postgres logs