IN subquery, many joins, very different plans

From: Dave Thorn <dave(dot)thorn(at)gmail(dot)com>
To: pgsql-performance(at)lists(dot)postgresql(dot)org
Subject: IN subquery, many joins, very different plans
Date: 2024-04-05 15:20:02
Message-ID: CAHSDwcmwSe+ixORhxK4AxKR=sDQ7ZUXWw=QXvuL8RKopk+pTtw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

Hi,

I have an issue with a query which has been migrated from a different
RDBMS where it performed in a second or so, and takes minutes to run
in postgresql 14.9 on AWS/RDS:

PostgreSQL 14.9 on aarch64-unknown-linux-gnu, compiled by
aarch64-unknown-linux-gnu-gcc (GCC) 9.5.0, 64-bit

The query looks mostly like this (table names changed, most fields
droppped out of the select):

------
select
AR.TABLE_D_PK as "AR.TABLE_D_PK",

from TABLE_A as GI

join TABLE_B as II on (II.TABLE_A_PK = GI.TABLE_A_PK and II.IS_DELETED =
'N')
join TABLE_C as GR on (GR.TABLE_A_PK = GI.TABLE_A_PK and GR.IS_DELETED =
'N')
join TABLE_D as AR on (GR.TABLE_D_PK = AR.TABLE_D_PK and AR.IS_DELETED =
'N')
join TABLE_E as IR on (GR.TABLE_C_PK = IR.TABLE_C_PK and IR.IS_DELETED =
'N')
join TABLE_F as MR on (IR.TABLE_F_PK = MR.TABLE_F_PK and MR.IS_DELETED =
'N')
join TABLE_N as MI on (MR.TABLE_N_PK = MI.TABLE_N_PK and MI.IS_DELETED =
'N')

left outer join TABLE_G as GM on (GR.TABLE_C_PK = GM.TABLE_C_PK and
GM.IS_DELETED = 'N')
left outer join TABLE_H as GY on (GR.TABLE_C_PK = GY.TABLE_C_PK and
GY.IS_DELETED = 'N')
left outer join TABLE_I as AC on (AR.TABLE_D_PK = AC.TABLE_D_PK and
AC.IS_DELETED = 'N')
left outer join TABLE_M as AA on (AR.TABLE_D_PK = AA.TABLE_D_PK and
AA.IS_DELETED = 'N')
left outer join TABLE_K as AP on (AR.TABLE_D_PK = AP.TABLE_D_PK and
AP.IS_DELETED = 'N')
left outer join TABLE_L as FP on (MR.TABLE_F_PK = FP.TABLE_F_PK and
FP.IS_DELETED = 'N')

--where AR.TABLE_D_PK = (
where AR.TABLE_D_PK IN (
--where AR.TABLE_D_PK = any(array (

select AA1.TABLE_D_PK from TABLE_M as AA1
join TABLE_D as AR1 on (AR1.TABLE_D_PK = AA1.TABLE_D_PK and
AR1.IS_DELETED = 'N')
where AA1.IS_DELETED = 'N' and AA1.TABLE_M_TYPE = 'ID_TYPE_X'
and ((AA1.TABLE_M_VALUE = 'SOME/UNIQUE/VALUE' and AR1.APP_CASE_TYPE
= '8' ))
-- limit 1

)
and GI.IS_DELETED = 'N'

------

The first interesting thing I noticed was that if I simplify the
subquery in various ways (such as looking up the TABLE_D_PK beforehand
and just inlining it there such as

where AR.TABLE_D_PK IN ( 123456 )

then it runs subsecond. Similarly if I change it from

where AR.TABLE_D_PK IN ( {select query} )

to either of the options listed there:

where AR.TABLE_D_PK = ( {select query} )
where AR.TABLE_D_PK = ANY(ARRAY( {select query} ) )

then it's also subsecond. It feels like postgresql is expecting the
subquery to return many rows and goes one way, whereas when it knows
it's only going to be 1 then it goes another (admittedly that doesn't
account for how ANY(ARRAY()) fixes it).

Or, it's as if the subquery is correlated, and so has to run for all the
rows
in the main query, but to my understanding it is an uncorrelated query.

Alternatively, if I strip some of the joins out, then I can leave the
original

where AR.TABLE_D_PK IN ( {select query} )

in place and it's still subsecond.

From here on the debugging bits I talk about are comparing the
original query listed at the top to the

where AR.TABLE_D_PK = ANY(ARRAY( {select query} ) )

version.

The query plans produced by the two are totally different:

(the mailing list page says to use attachments for big query plans,
and I've had to fallback to gmail to try to get through DKIM).

slow query -> attachment -> plan-slow-explain.txt
fast query -> attachment -> plan-fast-explain.txt

Plans with ANALYZE, BUFFERS, SETTINGS
slow query -> attachment -> plan-slow-explain-analyze.txt
fast query -> attachment -> plan-fast-explain-analyze.txt

The bit of code that generates this query CAN generate a subquery
(multiple options for SOME/UNIQUE/VALUE type affair) that returns a
list of TABLE_D_PKs, although in _this_ instance it's only finding
one. I did try adding LIMIT 1 to the subquery, thinking that that
would tell the planner there is only one row, and might make it behave
like the already-known-value case, or the = ( {subquery} case but it
does not.

I also found various suggestions online of adding OFFSET 0 to the
subquery, which also didn't improve anything.

(
I quickly get out of my depth with explain plans once it's not as
simple as "hey it's a seq scan when it should be an index", but one
thing that interests me here in the slow plan is where it does:

Workers Planned: 6
-> Hash Semi Join (cost=2666860.17..3131468.69 rows=1 width=24)
Hash Cond: (gr.TABLE_E_pk = ar1.TABLE_E_pk)
-> Parallel Hash Left Join (cost=2666851.92..3122476.95
rows=3422280 width=32)

because the "main" query doesn't join gr to ar1. It joins gr to ar.
ar1 is only in the subquery. I wonder if this suggests an initial
misstep in the plan that leads to minutes-not-subsecond.
)

I increased the default_statistics number to 10000 and reanalyzed, no
change.

Table counts:

select count(*) from TABLE_A; -- 19293000
select count(*) from TABLE_B; -- 19293000
select count(*) from TABLE_C; -- 21089144
select count(*) from TABLE_D; -- 21089144
select count(*) from TABLE_E; -- 21089144
select count(*) from TABLE_F; -- 21089144
select count(*) from TABLE_G; -- 6002192
select count(*) from TABLE_H; -- 21089147
select count(*) from TABLE_I; -- 5899661
select count(*) from TABLE_M; -- 21041076
select count(*) from TABLE_K; -- 375773
select count(*) from TABLE_L; -- 6571232
select count(*) from TABLE_M; -- 21041083
select count(*) from TABLE_N; -- 19293007

The tables are all indexed on the PK with INCLUDE (is_deleted)

Thanks for any guidance.

Dave

plan-slow-explain.txt

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=2667862.34..3132471.46 rows=1 width=8)
-> Nested Loop Left Join (cost=2667861.90..3132470.72 rows=1 width=16)
-> Nested Loop Left Join (cost=2667861.48..3132470.27 rows=1
width=16)
-> Nested Loop Left Join (cost=2667861.04..3132469.76
rows=1 width=16)
-> Nested Loop Left Join
(cost=2667860.61..3132469.29 rows=1 width=16)
-> Gather (cost=2667860.17..3132468.79 rows=1
width=24)
Workers Planned: 6
-> Hash Semi Join
(cost=2666860.17..3131468.69 rows=1 width=24)
Hash Cond: (gr.TABLE_E_pk =
ar1.TABLE_E_pk)
-> Parallel Hash Left Join
(cost=2666851.92..3122476.95 rows=3422280 width=32)
Hash Cond: (gr.TABLE_D_pk =
gm.TABLE_D_pk)
-> Parallel Hash Join
(cost=2519520.86..2960409.74 rows=3422280 width=32)
Hash Cond:
(gr.TABLE_A_pk = ii.TABLE_A_pk)
-> Parallel Hash Join
(cost=1732613.92..2146401.28 rows=3423649 width=40)
Hash Cond:
(mr.TABLE_O_pk = mi.TABLE_O_pk)
-> Parallel Hash
Join (cost=1384407.10..1789205.63 rows=3424314 width=48)
Hash Cond:
(gr.TABLE_E_pk = ar.TABLE_E_pk)
-> Parallel
Hash Join (cost=850104.36..1245854.83 rows=3446882 width=40)
Hash
Cond: (ir.TABLE_D_pk = gr.TABLE_D_pk)
->
Parallel Hash Join (cost=377639.61..764283.22 rows=3469280 width=24)

Hash Cond: (mr.TABLE_G_pk = ir.TABLE_G_pk)

-> Parallel Seq Scan on TABLE_G mr (cost=0.00..377476.70 rows=3492155
width=16)

Filter: (is_deleted = 'N'::bpchar)

-> Parallel Hash (cost=333991.70..333991.70 rows=3491833 width=16)

-> Parallel Seq Scan on TABLE_F ir (cost=0.00..333991.70
rows=3491833 width=16)

Filter: (is_deleted = 'N'::bpchar)
->
Parallel Hash (cost=428812.70..428812.70 rows=3492164 width=24)

-> Parallel Seq Scan on TABLE_D gr (cost=0.00..428812.70 rows=3492164
width=24)

Filter: (is_deleted = 'N'::bpchar)
-> Parallel
Hash (cost=490654.70..490654.70 rows=3491843 width=8)
->
Parallel Seq Scan on TABLE_E ar (cost=0.00..490654.70 rows=3491843
width=8)

Filter: (is_deleted = 'N'::bpchar)
-> Parallel Hash
(cost=307982.32..307982.32 rows=3217960 width=8)
-> Parallel
Seq Scan on TABLE_O mi (cost=0.00..307982.32 rows=3217960 width=8)

Filter: (is_deleted = 'N'::bpchar)
-> Parallel Hash
(cost=746729.28..746729.28 rows=3214213 width=16)
-> Parallel Hash
Join (cost=390397.57..746729.28 rows=3214213 width=16)
Hash Cond:
(ii.TABLE_A_pk = gi.TABLE_A_pk)
-> Parallel
Seq Scan on TABLE_C ii (cost=0.00..347892.74 rows=3214846 width=8)

Filter: (is_deleted = 'N'::bpchar)
-> Parallel
Hash (cost=350211.74..350211.74 rows=3214866 width=8)
->
Parallel Seq Scan on TABLE_A gi (cost=0.00..350211.74 rows=3214866
width=8)

Filter: (is_deleted = 'N'::bpchar)
-> Parallel Hash
(cost=132675.47..132675.47 rows=1172447 width=8)
-> Parallel Seq Scan on
TABLE_H gm (cost=0.00..132675.47 rows=1172447 width=8)
Filter:
(is_deleted = 'N'::bpchar)
-> Hash (cost=8.24..8.24 rows=1
width=16)
-> Nested Loop
(cost=1.00..8.24 rows=1 width=16)
-> Index Scan using
ix_TABLE_N_type_value_case on TABLE_N aa1 (cost=0.56..4.18 rows=1 width=8)
Index Cond:
(((TABLE_N_type)::text = 'ID_TYPE_X'::text) AND ((TABLE_N_value)::text =
'SOME/UNIQUE/VALUE'::text))
Filter:
(is_deleted = 'N'::bpchar)
-> Index Scan using
ix_TABLE_E_TABLE_E_pk on TABLE_E ar1 (cost=0.44..4.06 rows=1 width=8)
Index Cond:
(TABLE_E_pk = aa1.TABLE_E_pk)
Filter:
((is_deleted = 'N'::bpchar) AND ((app_case_type)::text = '8'::text))
-> Index Scan using ix_TABLE_I_TABLE_D_pk on
TABLE_I gy (cost=0.44..0.49 rows=1 width=8)
Index Cond: (TABLE_D_pk = gr.TABLE_D_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_J_TABLE_E_pk on TABLE_J
ac (cost=0.43..0.46 rows=1 width=8)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_N_TABLE_E_pk on TABLE_N aa
(cost=0.44..0.49 rows=1 width=8)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_L_TABLE_E_pk on TABLE_L ap
(cost=0.42..0.44 rows=1 width=8)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Only Scan using ix_TABLE_M_TABLE_G_pk on TABLE_M fp
(cost=0.43..0.64 rows=10 width=8)
Index Cond: ((TABLE_G_pk = mr.TABLE_G_pk) AND (is_deleted =
'N'::bpchar))
(68 rows)

plan-fast-explain.txt

QUERY PLAN
-
Nested Loop Left Join (cost=14.15..249.76 rows=10 width=8) (actual
time=0.227..0.233 rows=1 loops=1)
InitPlan 1 (returns $1)
-> Nested Loop (cost=1.00..8.24 rows=1 width=8) (actual
time=0.057..0.058 rows=1 loops=1)
-> Index Scan using ix_TABLE_N_type_value_case on TABLE_N aa1
(cost=0.56..4.18 rows=1 width=8) (actual time=0.039..0.040 rows=1 loops=1)
Index Cond: (((TABLE_N_type)::text = 'ID_TYPE_X'::text)
AND ((TABLE_N_value)::text = 'SOME/UNIQUE/VALUE'::text))
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_E_TABLE_E_pk on TABLE_E ar1
(cost=0.44..4.06 rows=1 width=8) (actual time=0.016..0.016 rows=1 loops=1)
Index Cond: (TABLE_E_pk = aa1.TABLE_E_pk)
Filter: ((is_deleted = 'N'::bpchar) AND
((app_case_type)::text = '8'::text))
-> Nested Loop Left Join (cost=5.48..234.10 rows=10 width=16) (actual
time=0.217..0.222 rows=1 loops=1)
-> Nested Loop Left Join (cost=5.05..193.62 rows=10 width=16)
(actual time=0.208..0.213 rows=1 loops=1)
-> Nested Loop Left Join (cost=4.62..152.99 rows=10
width=16) (actual time=0.196..0.201 rows=1 loops=1)
-> Nested Loop Left Join (cost=4.18..112.42 rows=10
width=16) (actual time=0.186..0.191 rows=1 loops=1)
-> Nested Loop Left Join (cost=3.75..107.42
rows=10 width=24) (actual time=0.172..0.176 rows=1 loops=1)
-> Nested Loop (cost=3.31..102.68
rows=10 width=24) (actual time=0.159..0.162 rows=1 loops=1)
-> Nested Loop (cost=2.88..97.81
rows=10 width=32) (actual time=0.144..0.147 rows=1 loops=1)
-> Nested Loop
(cost=2.44..92.88 rows=10 width=24) (actual time=0.131..0.134 rows=1
loops=1)
-> Nested Loop
(cost=1.88..86.62 rows=10 width=16) (actual time=0.118..0.119 rows=1
loops=1)
Join Filter:
(gi.TABLE_A_pk = ii.TABLE_A_pk)
-> Nested Loop
(cost=1.31..80.32 rows=10 width=32) (actual time=0.103..0.104 rows=1
loops=1)
-> Nested
Loop (cost=0.88..75.43 rows=10 width=24) (actual time=0.090..0.091 rows=1
loops=1)
->
Index Scan using ix_TABLE_E_TABLE_E_pk on TABLE_E ar (cost=0.44..34.90
rows=10 width=8) (actual time=0.073..0.074 rows=1 loops=1)

Index Cond: (TABLE_E_pk = ANY ($1))

Filter: (is_deleted = 'N'::bpchar)
->
Index Scan using uk_TABLE_D_TABLE_E_pk on TABLE_D gr (cost=0.44..4.05
rows=1 width=24) (actual time=0.016..0.016 rows=1 loops=1)

Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)

Filter: (is_deleted = 'N'::bpchar)
-> Index
Scan using ix_biog_id_biog_id_pk on TABLE_A gi (cost=0.44..0.49 rows=1
width=8) (actual time=0.012..0.012 rows=1 loops=1)
Index
Cond: (TABLE_A_pk = gr.TABLE_A_pk)

Filter: (is_deleted = 'N'::bpchar)
-> Index Scan
using ix_TABLE_C_mida on TABLE_C ii (cost=0.56..0.62 rows=1 width=8)
(actual time=0.014..0.014 rows=1 loops=1)
Index Cond:
(TABLE_A_pk = gr.TABLE_A_pk)
Filter:
(is_deleted = 'N'::bpchar)
-> Index Scan using
ix_TABLE_F_mida on TABLE_F ir (cost=0.56..0.62 rows=1 width=16) (actual
time=0.013..0.013 rows=1 loops=1)
Index Cond:
(TABLE_D_pk = gr.TABLE_D_pk)
Filter:
(is_deleted = 'N'::bpchar)
-> Index Scan using
pk_TABLE_G on TABLE_G mr (cost=0.44..0.49 rows=1 width=16) (actual
time=0.012..0.012 rows=1 loops=1)
Index Cond: (TABLE_G_pk
= ir.TABLE_G_pk)
Filter: (is_deleted =
'N'::bpchar)
-> Index Scan using ix_TABLE_O_mida
on TABLE_O mi (cost=0.44..0.49 rows=1 width=8) (actual time=0.015..0.015
rows=1 loops=1)
Index Cond: (TABLE_O_pk =
mr.TABLE_O_pk)
Filter: (is_deleted =
'N'::bpchar)
-> Index Scan using ix_TABLE_H_TABLE_D_pk
on TABLE_H gm (cost=0.43..0.46 rows=1 width=8) (actual time=0.012..0.012
rows=1 loops=1)
Index Cond: (TABLE_D_pk =
gr.TABLE_D_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_I_TABLE_D_pk on
TABLE_I gy (cost=0.44..0.49 rows=1 width=8) (actual time=0.014..0.014
rows=1 loops=1)
Index Cond: (TABLE_D_pk = gr.TABLE_D_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_J_TABLE_E_pk on TABLE_J
ac (cost=0.43..4.05 rows=1 width=8) (actual time=0.009..0.009 rows=0
loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_N_TABLE_E_pk on TABLE_N aa
(cost=0.44..4.05 rows=1 width=8) (actual time=0.011..0.011 rows=1 loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Scan using ix_TABLE_L_TABLE_E_pk on TABLE_L ap
(cost=0.42..4.04 rows=1 width=8) (actual time=0.008..0.008 rows=0 loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
-> Index Only Scan using ix_TABLE_M_TABLE_G_pk on TABLE_M fp
(cost=0.43..0.64 rows=10 width=8) (actual time=0.009..0.009 rows=0 loops=1)
Index Cond: ((TABLE_G_pk = mr.TABLE_G_pk) AND (is_deleted =
'N'::bpchar))
Heap Fetches: 0
Planning Time: 61.539 ms
Execution Time: 0.405 ms
(62 rows)

plan-slow-explain-analyze.txt

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=2667903.66..3132513.31 rows=1 width=8)
(actual time=200578.974..201810.300 rows=1 loops=1)
Buffers: shared hit=1610887 read=847496
I/O Timings: read=46389.959
-> Nested Loop Left Join (cost=2667903.22..3132512.57 rows=1 width=16)
(actual time=200578.953..201810.278 rows=1 loops=1)
Buffers: shared hit=1610884 read=847496
I/O Timings: read=46389.959
-> Nested Loop Left Join (cost=2667902.80..3132512.12 rows=1
width=16) (actual time=200578.934..201810.257 rows=1 loops=1)
Buffers: shared hit=1610881 read=847496
I/O Timings: read=46389.959
-> Nested Loop Left Join (cost=2667902.36..3132511.61
rows=1 width=16) (actual time=200578.908..201810.229 rows=1 loops=1)
Buffers: shared hit=1610877 read=847496
I/O Timings: read=46389.959
-> Nested Loop Left Join
(cost=2667901.93..3132511.14 rows=1 width=16) (actual
time=200578.888..201810.207 rows=1 loops=1)
Buffers: shared hit=1610874 read=847496
I/O Timings: read=46389.959
-> Gather (cost=2667901.49..3132510.64 rows=1
width=24) (actual time=200578.847..201810.161 rows=1 loops=1)
Workers Planned: 6
Workers Launched: 0
Buffers: shared hit=1610870 read=847496
I/O Timings: read=46389.959
-> Hash Semi Join
(cost=2666901.49..3131510.54 rows=1 width=24) (actual
time=200577.866..200786.512 rows=1 loops=1)
Hash Cond: (gr.TABLE_E_pk =
ar1.TABLE_E_pk)
Buffers: shared hit=1610870
read=847496
I/O Timings: read=46389.959
-> Parallel Hash Left Join
(cost=2666893.24..3122518.80 rows=3422280 width=32) (actual
time=115007.084..198452.799 rows=20955994 loops=1)
Hash Cond: (gr.TABLE_D_pk =
gm.TABLE_D_pk)
Buffers: shared hit=1610861
read=847496
I/O Timings: read=46389.959
-> Parallel Hash Join
(cost=2519520.86..2960409.74 rows=3422280 width=32) (actual
time=108933.021..180685.868 rows=20952150 loops=1)
Hash Cond:
(gr.TABLE_A_pk = ii.TABLE_A_pk)
Buffers: shared
hit=1493176 read=847478
I/O Timings:
read=46372.819
-> Parallel Hash Join
(cost=1732613.92..2146401.28 rows=3423649 width=40) (actual
time=71413.550..129338.033 rows=20952150 loops=1)
Hash Cond:
(mr.TABLE_O_pk = mi.TABLE_O_pk)
Buffers: shared
hit=875756 read=847181
I/O Timings:
read=46316.586
-> Parallel Hash
Join (cost=1384407.10..1789205.63 rows=3424314 width=48) (actual
time=53970.151..99631.531 rows=20952588 loops=1)
Hash Cond:
(gr.TABLE_E_pk = ar.TABLE_E_pk)
Buffers:
shared hit=875734 read=579453
I/O Timings:
read=32017.291
-> Parallel
Hash Join (cost=850104.36..1245854.83 rows=3446882 width=40) (actual
time=40670.584..73979.070 rows=20952588 loops=1)
Hash
Cond: (ir.TABLE_D_pk = gr.TABLE_D_pk)

Buffers: shared hit=431786 read=576682
I/O
Timings: read=31532.023
->
Parallel Hash Join (cost=377639.61..764283.22 rows=3469280 width=24)
(actual time=17370.113..37655.366 rows=20952588 loops=1)

Hash Cond: (mr.TABLE_G_pk = ir.TABLE_G_pk)

Buffers: shared hit=431746 read=191851

I/O Timings: read=11334.886

-> Parallel Seq Scan on TABLE_G mr (cost=0.00..377476.70 rows=3492155
width=16) (actual time=8.256..7628.867 rows=20952588 loops=1)

Filter: (is_deleted = 'N'::bpchar)

Rows Removed by Filter: 137463

Buffers: shared hit=333485 read=56

I/O Timings: read=99.651

-> Parallel Hash (cost=333991.70..333991.70 rows=3491833 width=16)
(actual time=17209.235..17209.236 rows=20952588 loops=1)

Buckets: 33554432 Batches: 1 Memory Usage: 1245280kB

Buffers: shared hit=98261 read=191795

I/O Timings: read=11235.235

-> Parallel Seq Scan on TABLE_F ir (cost=0.00..333991.70
rows=3491833 width=16) (actual time=10.521..8410.712 rows=20952588 loops=1)

Filter: (is_deleted = 'N'::bpchar)

Rows Removed by Filter: 137463

Buffers: shared hit=98261 read=191795

I/O Timings: read=11235.235
->
Parallel Hash (cost=428812.70..428812.70 rows=3492164 width=24) (actual
time=23231.120..23231.121 rows=20952588 loops=1)

Buckets: 33554432 Batches: 1 Memory Usage: 1410240kB

Buffers: shared hit=40 read=384831

I/O Timings: read=20197.137

-> Parallel Seq Scan on TABLE_D gr (cost=0.00..428812.70 rows=3492164
width=24) (actual time=1.548..13339.643 rows=20952588 loops=1)

Filter: (is_deleted = 'N'::bpchar)

Rows Removed by Filter: 137463

Buffers: shared hit=40 read=384831

I/O Timings: read=20197.137
-> Parallel
Hash (cost=490654.70..490654.70 rows=3491843 width=8) (actual
time=13214.241..13214.243 rows=20952588 loops=1)

Buckets: 33554432 Batches: 1 Memory Usage: 1081824kB

Buffers: shared hit=443948 read=2771
I/O
Timings: read=485.268
->
Parallel Seq Scan on TABLE_E ar (cost=0.00..490654.70 rows=3491843
width=8) (actual time=0.016..6391.132 rows=20952588 loops=1)

Filter: (is_deleted = 'N'::bpchar)

Rows Removed by Filter: 137463

Buffers: shared hit=443948 read=2771

I/O Timings: read=485.268
-> Parallel Hash
(cost=307982.32..307982.32 rows=3217960 width=8) (actual
time=17420.366..17420.366 rows=19289868 loops=1)
Buckets:
33554432 Batches: 1 Memory Usage: 1016768kB
Buffers:
shared hit=22 read=267728
I/O Timings:
read=14299.295
-> Parallel
Seq Scan on TABLE_O mi (cost=0.00..307982.32 rows=3217960 width=8) (actual
time=7.209..9860.853 rows=19289868 loops=1)

Filter: (is_deleted = 'N'::bpchar)
Rows
Removed by Filter: 3884

Buffers: shared hit=22 read=267728
I/O
Timings: read=14299.295
-> Parallel Hash
(cost=746729.28..746729.28 rows=3214213 width=16) (actual
time=37277.818..37277.821 rows=19289868 loops=1)
Buckets: 33554432
Batches: 1 Memory Usage: 1167264kB
Buffers: shared
hit=617420 read=297
I/O Timings:
read=56.233
-> Parallel Hash
Join (cost=390397.57..746729.28 rows=3214213 width=16) (actual
time=14977.066..30086.210 rows=19289868 loops=1)
Hash Cond:
(ii.TABLE_A_pk = gi.TABLE_A_pk)
Buffers:
shared hit=617420 read=297
I/O Timings:
read=56.233
-> Parallel
Seq Scan on TABLE_C ii (cost=0.00..347892.74 rows=3214846 width=8) (actual
time=0.010..5278.795 rows=19289868 loops=1)

Filter: (is_deleted = 'N'::bpchar)
Rows
Removed by Filter: 3884

Buffers: shared hit=307402 read=297
I/O
Timings: read=56.233
-> Parallel
Hash (cost=350211.74..350211.74 rows=3214866 width=8) (actual
time=14791.416..14791.417 rows=19289874 loops=1)

Buckets: 33554432 Batches: 1 Memory Usage: 1016768kB

Buffers: shared hit=310018
->
Parallel Seq Scan on TABLE_A gi (cost=0.00..350211.74 rows=3214866
width=8) (actual time=0.013..6388.707 rows=19289874 loops=1)

Filter: (is_deleted = 'N'::bpchar)

Rows Removed by Filter: 3878

Buffers: shared hit=310018
-> Parallel Hash
(cost=132712.68..132712.68 rows=1172776 width=8) (actual
time=6015.243..6015.244 rows=5863214 loops=1)
Buckets: 8388608
Batches: 1 Memory Usage: 294912kB
Buffers: shared
hit=117685 read=18
I/O Timings: read=17.141
-> Parallel Seq Scan on
TABLE_H gm (cost=0.00..132712.68 rows=1172776 width=8) (actual
time=0.016..2828.580 rows=5863214 loops=1)
Filter:
(is_deleted = 'N'::bpchar)
Rows Removed by
Filter: 139838
Buffers: shared
hit=117685 read=18
I/O Timings:
read=17.141
-> Hash (cost=8.24..8.24 rows=1
width=16) (actual time=0.062..0.064 rows=1 loops=1)
Buckets: 1024 Batches: 1
Memory Usage: 9kB
Buffers: shared hit=9
-> Nested Loop
(cost=1.00..8.24 rows=1 width=16) (actual time=0.048..0.050 rows=1 loops=1)
Buffers: shared hit=9
-> Index Scan using
ix_TABLE_N_type_value_case on TABLE_N aa1 (cost=0.56..4.18 rows=1 width=8)
(actual time=0.031..0.032 rows=1 loops=1)
Index Cond:
(((TABLE_N_type)::text = ID_TYPE_X'::text) AND ((TABLE_N_value)::text =
'SOME/UNIQUE/VALUE'::text))
Filter:
(is_deleted = 'N'::bpchar)
Buffers: shared
hit=5
-> Index Scan using
ix_TABLE_E_TABLE_E_pk on TABLE_E ar1 (cost=0.44..4.06 rows=1 width=8)
(actual time=0.014..0.014 rows=1 loops=1)
Index Cond:
(TABLE_E_pk = aa1.TABLE_E_pk)
Filter:
((is_deleted = 'N'::bpchar) AND ((app_case_type)::text = '8'::text))
Buffers: shared
hit=4
-> Index Scan using ix_TABLE_I_TABLE_D_pk on
TABLE_I gy (cost=0.44..0.49 rows=1 width=8) (actual time=0.037..0.038
rows=1 loops=1)
Index Cond: (TABLE_D_pk = gr.TABLE_D_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_J_TABLE_E_pk on TABLE_J
ac (cost=0.43..0.46 rows=1 width=8) (actual time=0.017..0.018 rows=0
loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=3
-> Index Scan using ix_TABLE_N_TABLE_E_pk on TABLE_N aa
(cost=0.44..0.49 rows=1 width=8) (actual time=0.023..0.024 rows=1 loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_L_TABLE_E_pk on TABLE_L ap
(cost=0.42..0.44 rows=1 width=8) (actual time=0.017..0.017 rows=0 loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=3
-> Index Only Scan using ix_TABLE_M_TABLE_G_pk on TABLE_M fp
(cost=0.43..0.64 rows=10 width=8) (actual time=0.018..0.018 rows=0 loops=1)
Index Cond: ((TABLE_G_pk = mr.TABLE_G_pk) AND (is_deleted =
'N'::bpchar))
Heap Fetches: 0
Buffers: shared hit=3
Settings: effective_cache_size = '43806080kB', maintenance_io_concurrency
= '1', max_parallel_workers_per_gather = '8', random_page_cost = '1.79769',
search_path = dbname, "$user", public', work_mem = '16GB'
Planning:
Buffers: shared hit=405
Planning Time: 178.009 ms
Execution Time: 201810.512 ms
(156 rows)

plan-fast-explain-analyze:

QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop Left Join (cost=14.15..249.76 rows=10 width=8) (actual
time=9.640..9.654 rows=1 loops=1)
Buffers: shared hit=59 read=1
I/O Timings: read=9.334
InitPlan 1 (returns $1)
-> Nested Loop (cost=1.00..8.24 rows=1 width=8) (actual
time=0.048..0.051 rows=1 loops=1)
Buffers: shared hit=9
-> Index Scan using ix_TABLE_N_type_value_case on TABLE_N aa1
(cost=0.56..4.18 rows=1 width=8) (actual time=0.031..0.032 rows=1 loops=1)
Index Cond: (((TABLE_N_type)::text = 'ID_TYPE_X'::text)
AND ((TABLE_N_value)::text = 'SOME/UNIQUE/VALUE'::text))
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=5
-> Index Scan using ix_TABLE_E_TABLE_E_pk on TABLE_E ar1
(cost=0.44..4.06 rows=1 width=8) (actual time=0.016..0.016 rows=1 loops=1)
Index Cond: (TABLE_E_pk = aa1.TABLE_E_pk)
Filter: ((is_deleted = 'N'::bpchar) AND
((app_case_type)::text = '8'::text))
Buffers: shared hit=4
-> Nested Loop Left Join (cost=5.48..234.10 rows=10 width=16) (actual
time=9.627..9.638 rows=1 loops=1)
Buffers: shared hit=56 read=1
I/O Timings: read=9.334
-> Nested Loop Left Join (cost=5.05..193.62 rows=10 width=16)
(actual time=9.615..9.626 rows=1 loops=1)
Buffers: shared hit=53 read=1
I/O Timings: read=9.334
-> Nested Loop Left Join (cost=4.62..152.99 rows=10
width=16) (actual time=9.600..9.610 rows=1 loops=1)
Buffers: shared hit=49 read=1
I/O Timings: read=9.334
-> Nested Loop Left Join (cost=4.18..112.42 rows=10
width=16) (actual time=9.586..9.596 rows=1 loops=1)
Buffers: shared hit=46 read=1
I/O Timings: read=9.334
-> Nested Loop Left Join (cost=3.75..107.42
rows=10 width=24) (actual time=9.569..9.577 rows=1 loops=1)
Buffers: shared hit=42 read=1
I/O Timings: read=9.334
-> Nested Loop (cost=3.31..102.68
rows=10 width=24) (actual time=9.552..9.559 rows=1 loops=1)
Buffers: shared hit=38 read=1
I/O Timings: read=9.334
-> Nested Loop (cost=2.88..97.81
rows=10 width=32) (actual time=9.531..9.538 rows=1 loops=1)
Buffers: shared hit=34 read=1
I/O Timings: read=9.334
-> Nested Loop
(cost=2.44..92.88 rows=10 width=24) (actual time=9.513..9.519 rows=1
loops=1)
Buffers: shared hit=30
read=1
I/O Timings: read=9.334
-> Nested Loop
(cost=1.88..86.62 rows=10 width=16) (actual time=9.476..9.481 rows=1
loops=1)
Join Filter:
(gi.TABLE_A_pk = ii.TABLE_A_pk)
Buffers: shared
hit=25 read=1
I/O Timings:
read=9.334
-> Nested Loop
(cost=1.31..80.32 rows=10 width=32) (actual time=0.097..0.101 rows=1
loops=1)
Buffers:
shared hit=21
-> Nested
Loop (cost=0.88..75.43 rows=10 width=24) (actual time=0.079..0.082 rows=1
loops=1)

Buffers: shared hit=17
->
Index Scan using ix_TABLE_E_TABLE_E_pk on TABLE_E ar (cost=0.44..34.90
rows=10 width=8) (actual time=0.064..0.066 rows=1 loops=1)

Index Cond: (TABLE_E_pk = ANY ($1))

Filter: (is_deleted = 'N'::bpchar)

Buffers: shared hit=13
->
Index Scan using uk_TABLE_D_TABLE_E_pk on TABLE_D gr (cost=0.44..4.05
rows=1 width=24) (actual time=0.014..0.014 rows=1 loops=1)

Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)

Filter: (is_deleted = 'N'::bpchar)

Buffers: shared hit=4
-> Index
Scan using pk_TABLE_A on TABLE_A gi (cost=0.44..0.49 rows=1 width=8)
(actual time=0.017..0.017 rows=1 loops=1)
Index
Cond: (TABLE_A_pk = gr.TABLE_A_pk)

Filter: (is_deleted = 'N'::bpchar)

Buffers: shared hit=4
-> Index Scan
using ix_TABLE_C_mida on TABLE_C ii (cost=0.56..0.62 rows=1 width=8)
(actual time=9.375..9.376 rows=1 loops=1)
Index Cond:
(TABLE_A_pk = gr.TABLE_A_pk)
Filter:
(is_deleted = 'N'::bpchar)
Buffers:
shared hit=4 read=1
I/O Timings:
read=9.334
-> Index Scan using
ix_TABLE_F_mida on TABLE_F ir (cost=0.56..0.62 rows=1 width=16) (actual
time=0.031..0.031 rows=1 loops=1)
Index Cond:
(TABLE_D_pk = gr.TABLE_D_pk)
Filter:
(is_deleted = 'N'::bpchar)
Buffers: shared
hit=5
-> Index Scan using
pk_TABLE_G on TABLE_G mr (cost=0.44..0.49 rows=1 width=16) (actual
time=0.015..0.015 rows=1 loops=1)
Index Cond: (TABLE_G_pk
= ir.TABLE_G_pk)
Filter: (is_deleted =
'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_O_mida
on TABLE_O mi (cost=0.44..0.49 rows=1 width=8) (actual time=0.018..0.019
rows=1 loops=1)
Index Cond: (TABLE_O_pk =
mr.TABLE_O_pk)
Filter: (is_deleted =
'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_H_TABLE_D_pk
on TABLE_H gm (cost=0.43..0.46 rows=1 width=8) (actual time=0.014..0.015
rows=1 loops=1)
Index Cond: (TABLE_D_pk =
gr.TABLE_D_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_I_TABLE_D_pk on
TABLE_I gy (cost=0.44..0.49 rows=1 width=8) (actual time=0.015..0.016
rows=1 loops=1)
Index Cond: (TABLE_D_pk = gr.TABLE_D_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_J_TABLE_E_pk on TABLE_J
ac (cost=0.43..4.05 rows=1 width=8) (actual time=0.012..0.012 rows=0
loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=3
-> Index Scan using ix_TABLE_N_TABLE_E_pk on TABLE_N aa
(cost=0.44..4.05 rows=1 width=8) (actual time=0.013..0.014 rows=1 loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=4
-> Index Scan using ix_TABLE_L_TABLE_E_pk on TABLE_L ap
(cost=0.42..4.04 rows=1 width=8) (actual time=0.009..0.009 rows=0 loops=1)
Index Cond: (TABLE_E_pk = ar.TABLE_E_pk)
Filter: (is_deleted = 'N'::bpchar)
Buffers: shared hit=3
-> Index Only Scan using ix_TABLE_M_TABLE_G_pk on TABLE_M fp
(cost=0.43..0.64 rows=10 width=8) (actual time=0.011..0.011 rows=0 loops=1)
Index Cond: ((TABLE_G_pk = mr.TABLE_G_pk) AND (is_deleted =
'N'::bpchar))
Heap Fetches: 0
Buffers: shared hit=3
Settings: effective_cache_size = '43806080kB', maintenance_io_concurrency
= '1', max_parallel_workers_per_gather = '8', random_page_cost = '1.79769',
search_path = dbname, "$user", public', work_mem = '16GB'
Planning:
Buffers: shared hit=381
Planning Time: 129.736 ms
Execution Time: 9.847 ms
(104 rows)

Attachment Content-Type Size
plan-slow-explain.txt text/plain 7.6 KB
plan-fast-explain.txt text/plain 6.9 KB
plan-slow-explain-analyze.txt text/plain 17.1 KB
plan-fast-explain-analyze.txt text/plain 9.7 KB

Browse pgsql-performance by date

  From Date Subject
Next Message James Pang 2024-04-09 03:07:49 LWlock:LockManager waits
Previous Message Laurenz Albe 2024-03-19 17:54:21 Re: maintenance_work_mem impact?