BUG #14871: RLS join query plan

From: banzaitron(at)comcast(dot)net
To: pgsql-bugs(at)postgresql(dot)org
Cc: banzaitron(at)comcast(dot)net
Subject: BUG #14871: RLS join query plan
Date: 2017-10-24 23:31:49
Message-ID: 20171024233149.1478.21053@wrigleys.postgresql.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

The following bug has been logged on the website:

Bug reference: 14871
Logged by: Andy Kinney
Email address: banzaitron(at)comcast(dot)net
PostgreSQL version: 10.0
Operating system: CentOS7
Description:

Hello,
I apologize if this is submitted to the wrong place, let me know if I need
to send it elsewhere (I am having a hard time finding info on this). We
chose Postgresql for a fairly large project because of its recent support
for RLS. I understand there were some performance problems early on in 9.6
related to joins of large tables. My understanding is that those were
resolved in 10.0. I am experiencing some very strange query plans with and
without RLS enabled. The optimizer is performing sequential scans of a huge
table when enabled. Here is a plan showing the difference with and without
(Elset is a large table, Onorbit is smaller (about 20000 rows), and
Currentelset is a table that maps a single 'current' Elset row for each
Onorbit row). Each PK/FK have appropriate indices defined and queries
against the large table alone are very fast so I believe the POLICY I've put
on the table is not the issue:

explain (buffers, analyze)
select
elset0_.*
from
"Currentelset" currentels3_
inner join
"Elset" elset0_
on currentels3_."idElset"=elset0_."idElset"
inner join
"Onorbit" onorbit1_
on elset0_."OnOrbit_idOnOrbit"=onorbit1_."idOnOrbit"

QUERY
PLAN

----------------------------------------------------------------------------------------------------
----------------------------------------------
Nested Loop (cost=689.08..49670.49 rows=1058 width=378) (actual
time=2832.039..102802.046 rows=169
24 loops=1)
Buffers: shared hit=7136232 read=2618
-> Hash Join (cost=688.79..48017.34 rows=4231 width=378) (actual
time=2831.915..100814.347 rows
=16924 loops=1)
Hash Cond: ((elset0_."idElset")::text =
(currentels3_."idElset")::text)
Buffers: shared hit=6966945 read=2618
-> Seq Scan on "Elset" elset0_ (cost=0.00..46037.32 rows=102276
width=378) (actual time=0
.392..100401.072 rows=409104 loops=1)
Filter: ((SubPlan 1) AND (SubPlan 2))
Buffers: shared hit=6966637 read=2618
SubPlan 1
-> Result (cost=0.00..0.04 rows=1 width=1) (actual
time=0.185..0.185 rows=1 loops
=409104)
Buffers: shared hit=5319530
SubPlan 2
-> Result (cost=0.00..0.04 rows=1 width=1) (actual
time=0.057..0.057 rows=1 loops
=409104)
Buffers: shared hit=1636416
-> Hash (cost=477.24..477.24 rows=16924 width=37) (actual
time=7.707..7.707 rows=16924 lo
ops=1)
Buckets: 32768 Batches: 1 Memory Usage: 1397kB
Buffers: shared hit=308
-> Seq Scan on "Currentelset" currentels3_
(cost=0.00..477.24 rows=16924 width=37)
(actual time=0.008..3.519 rows=16924 loops=1)
Buffers: shared hit=308
-> Index Scan using onorbit_pkey on "Onorbit" onorbit1_
(cost=0.29..0.39 rows=1 width=5) (actua
l time=0.115..0.115 rows=1 loops=16924)
Index Cond: (("idOnOrbit")::text =
(elset0_."OnOrbit_idOnOrbit")::text)
Filter: ((SubPlan 3) AND (SubPlan 4))
Buffers: shared hit=169287
SubPlan 3
-> Result (cost=0.00..0.04 rows=1 width=1) (actual
time=0.050..0.050 rows=1 loops=16924
)
Buffers: shared hit=50772
SubPlan 4
-> Result (cost=0.00..0.04 rows=1 width=1) (actual
time=0.053..0.053 rows=1 loops=16924
)
Buffers: shared hit=67696
Planning time: 0.934 ms
Execution time: 102805.236 ms
(31 rows)

Without RLS:

explain (buffers, analyze)
select
elset0_.*
from
"Currentelset" currentels3_
inner join
"Elset" elset0_
on currentels3_."idElset"=elset0_."idElset"
inner join
"Onorbit" onorbit1_
on elset0_."OnOrbit_idOnOrbit"=onorbit1_."idOnOrbit"

QUERY
PLAN

----------------------------------------------------------------------------------------------------
----------------------------------------------------
Gather (cost=2461.39..21408.48 rows=16924 width=378) (actual
time=27.768..123.132 rows=16924 loops
=1)
Workers Planned: 2
Workers Launched: 2
Buffers: shared hit=13167 read=2588
-> Hash Join (cost=1461.39..18716.08 rows=7052 width=378) (actual
time=39.811..106.877 rows=564
1 loops=3)
Hash Cond: ((elset0_."OnOrbit_idOnOrbit")::text =
(onorbit1_."idOnOrbit")::text)
Buffers: shared hit=12817 read=2586
-> Hash Join (cost=688.79..17854.45 rows=7052 width=378) (actual
time=24.560..87.577 rows
=5641 loops=3)
Hash Cond: ((elset0_."idElset")::text =
(currentels3_."idElset")::text)
Buffers: shared hit=11647 read=2586
-> Parallel Seq Scan on "Elset" elset0_
(cost=0.00..15013.60 rows=170460 width=378)
(actual time=0.040..38.353 rows=136368 loops=3)
Buffers: shared hit=10723 read=2586
-> Hash (cost=477.24..477.24 rows=16924 width=37) (actual
time=9.986..9.986 rows=16
924 loops=3)
Buckets: 32768 Batches: 1 Memory Usage: 1397kB
Buffers: shared hit=924
-> Seq Scan on "Currentelset" currentels3_
(cost=0.00..477.24 rows=16924 widt
h=37) (actual time=0.026..4.435 rows=16924 loops=3)
Buffers: shared hit=924
-> Hash (cost=536.71..536.71 rows=18871 width=5) (actual
time=14.747..14.747 rows=18871 l
oops=3)
Buckets: 32768 Batches: 1 Memory Usage: 954kB
Buffers: shared hit=1044
-> Seq Scan on "Onorbit" onorbit1_ (cost=0.00..536.71
rows=18871 width=5) (actual t
ime=0.033..7.587 rows=18871 loops=3)
Buffers: shared hit=1044
Planning time: 1.478 ms
Execution time: 127.713 ms
(24 rows)

Browse pgsql-bugs by date

  From Date Subject
Next Message Stefan Tzeggai 2017-10-25 12:16:39 Segfault 11 on PG10 with max_parallel_workers_per_gather>3
Previous Message andreigorita 2017-10-24 15:53:58 BUG #14870: wrong query results when using WITH with UPDATE