[prev in list] [next in list] [prev in thread] [next in thread]
List: postgresql-general
Subject: Bad Estimate for multi tenant database queries
From: Peter Grman <peter.grman () gmail ! com>
Date: 2019-08-29 20:54:04
Message-ID: CACF7Wx36G0YBM7xjDhZkG1d_B8jgD6Q=WFCrk7o=exNiniom1g () mail ! gmail ! com
[Download RAW message or body]
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 (cost034.74..22788.40 rows346 widthy3) (actual
time#.815..57.178 rows263 loops=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit997
-> Hash Join (cost034.74..20553.80 rowsQ44 widthy3) (actual
time .869..49.029 rows@88 loops=3)
Hash Cond: (r."TimeSliceDefinitionId" = t."Id")
Buffers: shared hit997
-> Parallel Hash Join (cost907.55..20413.09 rowsQ44
widthf2) (actual time.210..45.177 rows@88 loops=3)
Hash Cond: (f."Id" = r."NoShowFeeId")
Buffers: shared hit683
-> Parallel Seq Scan on "NoShowFee" f (cost=0.00..7343.25
rowsa825 width3) (actual time=0.006..15.481 rowsI460 loops=3)
Buffers: shared hitg25
-> Parallel Hash (cost843.25..12843.25 rowsQ44
widthQ9) (actual time.071..19.072 rows@88 loops=3)
Buckets: 16384 Batches: 1 Memory Usage: 4832kB
Buffers: shared hit958
-> Parallel Seq Scan on "Reservation" r
(cost=0.00..12843.25 rowsQ44 widthQ9) (actual time=0.971..14.919
rows@88 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 hit958
-> Hash (cost.53..96.53 rows$53 width1) (actual
time=1.586..1.586 rows$53 loops=3)
Buckets: 4096 Batches: 1 Memory Usage: 457kB
Buffers: shared hit!6
-> Seq Scan on "TimeSliceDefinition" t (cost=0.00..96.53
rows$53 width1) (actual time=0.009..0.697 rows$53 loops=3)
Buffers: shared hit!6
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 (costA9.37..6656.11 rows=3 widthy3) (actual
time=1.367..95.051 rows92 loops=1)
Buffers: shared hitA970
-> Nested Loop (costA8.95..6504.77 rowsI widthe0) (actual
time=1.355..49.789 rows92 loops=1)
Buffers: shared hitY80
-> Bitmap Heap Scan on "TimeSliceDefinition" t (cost=4.39..39.99
rows width1) (actual time=0.015..0.035 rows 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 width=0) (actual time=0.010..0.010 rows loops=1)
Index Cond: ("AccountCode" = 'Code1'::text)
Buffers: shared hit=2
-> Bitmap Heap Scan on "Reservation" r (costA4.56..461.66
rows widthQ9) (actual time=1.104..2.987 rowsd2 loops)
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: exactG76
Buffers: shared hitY71
-> BitmapAnd (costA4.56..414.56 rows width=0) (actual
time=1.057..1.057 rows=0 loops)
Buffers: shared hit95
-> Bitmap Index Scan on
"IX_Reservation_TimeSliceDefinitionId" (cost=0.00..13.84 rows9 width=0)
(actual time=0.063..0.063 rowsf5 loops)
Index Cond: ("TimeSliceDefinitionId" = t."Id")
Buffers: shared hit
-> Bitmap Index Scan on
"IX_Reservation_AccountCode_EntityId" (cost=0.00..398.31 rows86
width=0) (actual time=1.056..1.056 rows25 loops)
Index Cond: ("AccountCode" = 'Code1'::text)
Buffers: shared hit05
-> Index Scan using "PK_NoShowFee" on "NoShowFee" f (cost=0.42..3.09
rows=1 width3) (actual time=0.003..0.003 rows=1 loops92)
Index Cond: ("Id" = r."NoShowFeeId")
Filter: ("AccountCode" = 'Code1'::text)
Buffers: shared hit5990
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
[Attachment #3 (text/html)]
<div dir="ltr">Hello,<div><br></div><div>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):</div><div><br></div><div>explain (ANALYZE, COSTS, BUFFERS, FORMAT \
text)<br> select *<br> from "Reservation"."Reservation" \
r<br> join "Rates"."TimeSliceDefinition" t on \
r."TimeSliceDefinitionId" = t."Id"<br> join \
"Reservation"."NoShowFee" f on r."NoShowFeeId" = \
f."Id"<br> where r."DepartureUtc" > '2018-01-01' \
and r."ArrivalUtc" < '2018-09-30'<br><br>Gather \
(cost=14034.74..22788.40 rows=12346 width=793) (actual time=23.815..57.178 rows=12263 \
loops=1)<br> Workers Planned: 2<br> Workers Launched: 2<br> Buffers: shared \
hit=18997<br> -> Hash Join (cost=13034.74..20553.80 rows=5144 width=793) \
(actual time=20.869..49.029 rows=4088 loops=3)<br> Hash Cond: \
(r."TimeSliceDefinitionId" = t."Id")<br> Buffers: \
shared hit=18997<br> -> Parallel Hash Join (cost=12907.55..20413.09 \
rows=5144 width=662) (actual time=19.210..45.177 rows=4088 loops=3)<br> \
Hash Cond: (f."Id" = r."NoShowFeeId")<br> \
Buffers: shared hit=18683<br> -> 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)<br> Buffers: \
shared hit=6725<br> -> Parallel Hash \
(cost=12843.25..12843.25 rows=5144 width=519) (actual time=19.071..19.072 rows=4088 \
loops=3)<br> Buckets: 16384 Batches: 1 Memory Usage: \
4832kB<br> Buffers: shared hit=11958<br> \
-> 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)<br> \
Filter: (("DepartureUtc" > '2018-01-01 00:00:00'::timestamp \
without time zone) AND ("ArrivalUtc" < '2018-09-30 \
00:00:00'::timestamp without time zone))<br> \
Rows Removed by Filter: 43126<br> Buffers: \
shared hit=11958<br> -> Hash (cost=96.53..96.53 rows=2453 \
width=131) (actual time=1.586..1.586 rows=2453 loops=3)<br> \
Buckets: 4096 Batches: 1 Memory Usage: 457kB<br> Buffers: \
shared hit=216<br> -> Seq Scan on \
"TimeSliceDefinition" t (cost=0.00..96.53 rows=2453 width=131) (actual \
time=0.009..0.697 rows=2453 loops=3)<br> Buffers: shared \
hit=216<br>Planning Time: 0.424 ms<br>Execution Time: 58.146 \
ms<br></div><div><br></div><div>and with tenant separation (wrong \
estimates):</div><div><br></div><div>explain (ANALYZE, COSTS, BUFFERS, FORMAT \
text)<br> select *<br> from "Reservation"."Reservation" \
r<br> join "Rates"."TimeSliceDefinition" t on \
r."TimeSliceDefinitionId" = t."Id"<br> join \
"Reservation"."NoShowFee" f on r."NoShowFeeId" = \
f."Id"<br> where r."DepartureUtc" > '2018-01-01' \
and r."ArrivalUtc" < '2019-12-31' and r."AccountCode" \
= 'Code1' and t."AccountCode" = 'Code1' and \
f."AccountCode" = 'Code1'<br><br>Nested Loop \
(cost=419.37..6656.11 rows=3 width=793) (actual time=1.367..95.051 rows=8992 \
loops=1)<br> Buffers: shared hit=41970<br> -> Nested Loop \
(cost=418.95..6504.77 rows=49 width=650) (actual time=1.355..49.789 rows=8992 \
loops=1)<br> Buffers: shared hit=5980<br> -> 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)<br> Recheck Cond: \
("AccountCode" = 'Code1'::text)<br> Heap \
Blocks: exact=7<br> Buffers: shared hit=9<br> \
-> 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)<br> \
Index Cond: ("AccountCode" = 'Code1'::text)<br> \
Buffers: shared hit=2<br> -> 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)<br> Recheck Cond: \
(("TimeSliceDefinitionId" = t."Id") AND ("AccountCode" \
= 'Code1'::text))<br> Filter: (("DepartureUtc" \
> '2018-01-01 00:00:00'::timestamp without time zone) AND \
("ArrivalUtc" < '2019-12-31 00:00:00'::timestamp without time \
zone))<br> Rows Removed by Filter: 14<br> \
Heap Blocks: exact=4776<br> Buffers: shared hit=5971<br> \
-> BitmapAnd (cost=414.56..414.56 rows=12 width=0) (actual time=1.057..1.057 \
rows=0 loops=14)<br> Buffers: shared hit=1195<br> \
-> 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)<br> \
Index Cond: ("TimeSliceDefinitionId" = t."Id")<br> \
Buffers: shared hit=90<br> -> 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)<br> \
Index Cond: ("AccountCode" = 'Code1'::text)<br> \
Buffers: shared hit=1105<br> -> 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)<br> Index Cond: ("Id" = \
r."NoShowFeeId")<br> Filter: ("AccountCode" = \
'Code1'::text)<br> Buffers: shared hit=35990<br>Planning Time: \
0.766 ms<br>Execution Time: 95.687 ms<br></div><div><br></div><div>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 \
<a href="https://www.postgresql.org/message-id/CAFh58O_Myr6G3tcH3gcGrF-=OExB08PJdWZcSBcEcovaiPsrHA@mail.gmail.com" \
target="_blank">https://www.postgresql.org/message-id/CAFh58O_Myr6G3tcH3gcGrF-=OExB08PJdWZcSBcEcovaiPsrHA@mail.gmail.com</a> \
and tried the same query with SET enable_nestloop=OFF - it took 200ms when it used \
HASH JOINs</div><div><br></div><div>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:</div><div><br></div><div>CREATE STATISTICS \
MT_ReservationDepartureUtc (ndistinct) on "AccountCode", \
"DepartureUtc" from \
"Reservation"."Reservation";<br>CREATE STATISTICS \
MT_ReservationArrivalUtc (ndistinct) on "AccountCode", \
"ArrivalUtc" from \
"Reservation"."Reservation";<br>CREATE STATISTICS \
MT_ReservationNoShowFeeId (ndistinct) on "AccountCode", \
"NoShowFeeId" from \
"Reservation"."Reservation";<br>CREATE STATISTICS \
MT_ReservationTimeSliceDefinitionId (ndistinct) on "AccountCode", \
"TimeSliceDefinitionId" from \
"Reservation"."Reservation";<br></div><div><br></div><div>but \
that didn't help either</div><div><br></div><div>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</div><div><br></div><div>How can I help postgres to collect the \
correct data?</div><div><br></div><div>Thank you,</div><div>Peter</div></div>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic