Home > mailing lists

NL Join vs Merge Join - 5 hours vs 2 seconds - Mailing list pgsql-general

From	Kumar, Virendra
Subject	NL Join vs Merge Join - 5 hours vs 2 seconds
Date	December 17, 2018 18:42:20
Msg-id	e86620f9f6a94838b513e2218f0cef55@USFKL11XG20CN01.mercer.com Whole thread Raw
Responses	Re: NL Join vs Merge Join - 5 hours vs 2 seconds (Tom Lane <tgl@sss.pgh.pa.us>)
List	pgsql-general

Tree view

We are using Postgers-XL based on PostgreSQL 10.5 on RHEL7. We have an extreme case of one query which running in 4 hour 45 mins and 33 seconds with Nested Loops Join vs 2.5 seconds when we disable enable_nestloop. The query is given below. I would be happy to share more information if required.

Plan A - NL enabled:

Limit (cost=78922.65..87812.39 rows=1 width=584) (actual time=53476.337..17133622.713 rows=353 loops=1)

Buffers: shared hit=181422132, temp read=50909275 written=50909273

-> GroupAggregate (cost=78922.65..87812.39 rows=1 width=584) (actual time=53476.334..17133622.035 rows=353 loops=1)

Group Key: sh."row", sh.col

Buffers: shared hit=181422132, temp read=50909275 written=50909273

-> Nested Loop (cost=78922.65..87812.20 rows=1 width=536) (actual time=51768.638..17132518.985 rows=51562 loops=1)

Join Filter: ((se.account_id = pe.account_id) AND (se.peril_id = pe.peril_id))

Rows Removed by Join Filter: 2403022205

Buffers: shared hit=181422132, temp read=50909275 written=50909273

-> GroupAggregate (cost=72432.96..72433.14 rows=1 width=368) (actual time=51513.891..52815.004 rows=51567 loops=1)

Group Key: sh."row", sh.col, se.portfolio_id, se.peril_id, se.account_id

Buffers: shared hit=22235530, temp read=7878 written=7876

-> Sort (cost=72432.96..72432.96 rows=1 width=324) (actual time=51513.864..51790.397 rows=111621 loops=1)

Sort Key: sh."row", sh.col, se.peril_id, se.account_id

Sort Method: external merge Disk: 36152kB

Buffers: shared hit=22235530, temp read=7878 written=7876

-> Nested Loop Semi Join (cost=34681.42..72432.95 rows=1 width=324) (actual time=238.805..51120.362 rows=111621 loops=1)

Join Filter: (a.account_id = se1.account_id)

Buffers: shared hit=22235530, temp read=3359 written=3353

-> Gather (cost=34681.00..72431.43 rows=1 width=348) (actual time=238.757..1085.453 rows=111621 loops=1)

Workers Planned: 2

Workers Launched: 2

Buffers: shared hit=421611, temp read=3359 written=3353

-> Nested Loop (cost=33681.00..71431.33 rows=1 width=348) (actual time=359.006..926.303 rows=37207 loops=3)

Join Filter: (se.account_id = a.account_id)

Buffers: shared hit=421611, temp read=3359 written=3353

-> Hash Join (cost=33680.71..71298.94 rows=395 width=300) (actual time=358.953..656.923 rows=36828 loops=3)

Hash Cond: ((se.account_id = sh.account_id) AND (se.site_id = sh.site_id))

Buffers: shared hit=89803, temp read=3359 written=3353

-> Parallel Bitmap Heap Scan on site_exposure_p1000013 se (cost=2447.82..32716.49 rows=15266 width=276) (actual time=4.980..165.908 rows=36639 loops=3)

Recheck Cond: (shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry)

Filter: ((portfolio_id = 1000013) AND _st_intersects(shape, '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry))

Heap Blocks: exact=2704

Buffers: shared hit=16522

-> Bitmap Index Scan on site_exposure_p1000013_shape_idx (cost=0.00..2438.66 rows=109917 width=0) (actual time=12.154..12.155 rows=109917 loops=1)

Index Cond: (shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry)

Buffers: shared hit=797

-> Hash (cost=28094.08..28094.08 rows=143721 width=28) (actual time=352.223..352.224 rows=144202 loops=3)

Buckets: 262144 Batches: 2 Memory Usage: 6556kB

Buffers: shared hit=73223, temp written=1371

-> Bitmap Heap Scan on site_hex_bin_p1000013 sh (cost=1904.27..28094.08 rows=143721 width=28) (actual time=15.842..252.047 rows=144202 loops=3)

Recheck Cond: (lod = 5)

Filter: (portfolio_id = 1000013)

Heap Blocks: exact=24008

Buffers: shared hit=73223

-> Bitmap Index Scan on site_hex_bin_p1000013_lod_idx (cost=0.00..1868.34 rows=143721 width=0) (actual time=12.614..12.615 rows=144202 loops=3)

Index Cond: (lod = 5)

Buffers: shared hit=1199

-> Index Scan using account_p1000013_account_id_idx on account_p1000013 a (cost=0.29..0.32 rows=1 width=52) (actual time=0.003..0.005 rows=1 loops=110485)

Index Cond: (account_id = sh.account_id)

Filter: (portfolio_id = 1000013)

Buffers: shared hit=331808

-> Index Scan using site_exposure_p1000013_account_id_idx on site_exposure_p1000013 se1 (cost=0.42..1.50 rows=1 width=16) (actual time=0.446..0.446 rows=1 loops=111621)

Index Cond: (account_id = sh.account_id)

Filter: ((shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry) AND (portfolio_id = 1000013) AND (sh.site_id = site_id) AND _st_intersects(shape, '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry))

Rows Removed by Filter: 1504

Buffers: shared hit=21813919

-> Finalize GroupAggregate (cost=6489.69..14214.02 rows=46601 width=200) (actual time=98.190..313.002 rows=46601 loops=51567)

Group Key: pe.peril_id, pe.portfolio_id, pe.account_id

Buffers: shared hit=122339289, temp read=50900403 written=50900403

-> Gather Merge (cost=6489.69..11897.85 rows=28464 width=200) (actual time=98.174..229.739 rows=46604 loops=51567)

Workers Planned: 1

Workers Launched: 1

Buffers: shared hit=122340016, temp read=50900403 written=50900403

-> Partial GroupAggregate (cost=5489.68..7695.64 rows=28464 width=200) (actual time=62.035..118.505 rows=23302 loops=103134)

Group Key: pe.peril_id, pe.portfolio_id, pe.account_id

Buffers: shared hit=159187329, temp read=50901397 written=50901397

-> Sort (cost=5489.68..5560.84 rows=28464 width=200) (actual time=61.104..75.010 rows=24194 loops=103134)

Sort Key: pe.peril_id, pe.account_id

Sort Method: external sort Disk: 7896kB

Buffers: shared hit=159187329, temp read=50901397 written=50901397

-> Parallel Seq Scan on policy_exposure_p1000013 pe (cost=0.00..3383.79 rows=28464 width=200) (actual time=0.021..25.688 rows=24194 loops=103134)

Filter: (portfolio_id = 1000013)

Buffers: shared hit=156144876 Planning time: 6.990 ms Execution time: 17133656.822 ms

(76 rows)

Time: 17133669.350 ms (04:45:33.669)

Plan B - NL disabled:

Limit (cost=121789.91..121790.10 rows=1 width=584) (actual time=2561.184..2695.610 rows=353 loops=1)

Buffers: shared hit=60394, temp read=17144 written=17147

-> GroupAggregate (cost=121789.91..121790.10 rows=1 width=584) (actual time=2561.181..2695.345 rows=353 loops=1)

Group Key: s.sh_row, s.sh_col

Buffers: shared hit=60394, temp read=17144 written=17147

-> Sort (cost=121789.91..121789.92 rows=1 width=536) (actual time=2561.103..2599.304 rows=51562 loops=1)

Sort Key: s.sh_row, s.sh_col

Sort Method: external merge Disk: 27304kB

Buffers: shared hit=60394, temp read=17144 written=17147

-> Merge Join (cost=113366.54..121789.90 rows=1 width=536) (actual time=2105.426..2442.405 rows=51562 loops=1)

Merge Cond: ((pe.peril_id = s.se_peril_id) AND (pe.account_id = s.se_account_id))

Buffers: shared hit=60394, temp read=13731 written=13731

-> Finalize GroupAggregate (cost=6489.69..14214.02 rows=46601 width=200) (actual time=84.618..292.694 rows=46601 loops=1)

Group Key: pe.peril_id, pe.portfolio_id, pe.account_id

Buffers: shared hit=2165

-> Gather Merge (cost=6489.69..11897.85 rows=28464 width=200) (actual time=84.602..207.781 rows=46605 loops=1)

Workers Planned: 1

Workers Launched: 1

Buffers: shared hit=3087

-> Partial GroupAggregate (cost=5489.68..7695.64 rows=28464 width=200) (actual time=59.728..115.224 rows=23302 loops=2)

Group Key: pe.peril_id, pe.portfolio_id, pe.account_id

Buffers: shared hit=3087

-> Sort (cost=5489.68..5560.84 rows=28464 width=200) (actual time=59.706..69.961 rows=24194 loops=2)

Sort Key: pe.peril_id, pe.account_id

Sort Method: quicksort Memory: 10018kB

Buffers: shared hit=3087

-> Parallel Seq Scan on policy_exposure_p1000013 pe (cost=0.00..3383.79 rows=28464 width=200) (actual time=0.026..37.045 rows=24194 loops=2)

Filter: (portfolio_id = 1000013)

Buffers: shared hit=3028

-> Sort (cost=106876.85..106876.85 rows=1 width=368) (actual time=2020.792..2058.011 rows=51567 loops=1)

Sort Key: s.se_peril_id, s.se_account_id

Sort Method: external sort Disk: 19040kB

Buffers: shared hit=58229, temp read=13731 written=13731

-> Subquery Scan on s (cost=106876.64..106876.84 rows=1 width=368) (actual time=1430.482..1792.003 rows=51567 loops=1)

Buffers: shared hit=58229, temp read=8972 written=8971

-> GroupAggregate (cost=106876.64..106876.83 rows=1 width=368) (actual time=1430.479..1747.379 rows=51567 loops=1)

Group Key: sh."row", sh.col, se.portfolio_id, se.peril_id, se.account_id

Buffers: shared hit=58229, temp read=8972 written=8971

-> Sort (cost=106876.64..106876.65 rows=1 width=324) (actual time=1430.423..1521.130 rows=111621 loops=1)

Sort Key: sh."row", sh.col, se.peril_id, se.account_id

Sort Method: external merge Disk: 36160kB

Buffers: shared hit=58229, temp read=8972 written=8971

-> Hash Join (cost=79603.30..106876.63 rows=1 width=324) (actual time=622.718..1190.648 rows=111621 loops=1)

Hash Cond: (se.account_id = a.account_id)

Buffers: shared hit=58229, temp read=4452 written=4446

-> Hash Join (cost=77643.95..104913.92 rows=225 width=300) (actual time=565.028..965.081 rows=110485 loops=1)

Hash Cond: ((sh.account_id = se.account_id) AND (sh.site_id = se.site_id))

Buffers: shared hit=57449, temp read=4452 written=4446

-> Bitmap Heap Scan on site_hex_bin_p1000013 sh (cost=1904.27..28094.08 rows=143721 width=28) (actual time=12.622..133.905 rows=144202 loops=1)

Recheck Cond: (lod = 5)

Filter: (portfolio_id = 1000013)

Heap Blocks: exact=24008

Buffers: shared hit=24405

-> Bitmap Index Scan on site_hex_bin_p1000013_lod_idx (cost=0.00..1868.34 rows=143721 width=0) (actual time=9.465..9.465 rows=144202 loops=1)

Index Cond: (lod = 5)

Buffers: shared hit=397

-> Hash (cost=75609.24..75609.24 rows=8696 width=292) (actual time=552.359..552.359 rows=109917 loops=1)

Buckets: 32768 (originally 16384) Batches: 4 (originally 1) Memory Usage: 9985kB

Buffers: shared hit=33044, temp written=3115

-> Hash Semi Join (cost=41377.79..75609.24 rows=8696 width=292) (actual time=204.061..423.813 rows=109917 loops=1)

Hash Cond: ((se.account_id = se1.account_id) AND (se.site_id = se1.site_id))

Buffers: shared hit=33044

-> Gather (cost=3447.82..37380.39 rows=36639 width=276) (actual time=16.265..104.149 rows=109917 loops=1)

Workers Planned: 2

Workers Launched: 2

Buffers: shared hit=16522

-> Parallel Bitmap Heap Scan on site_exposure_p1000013 se (cost=2447.82..32716.49 rows=15266 width=276) (actual time=5.159..127.909 rows=36639 loops=3)

Heap Blocks: exact=87

Buffers: shared hit=16522

-> Bitmap Index Scan on site_exposure_p1000013_shape_idx (cost=0.00..2438.66 rows=109917 width=0) (actual time=12.634..12.635 rows=109917 loops=1)

Buffers: shared hit=797

-> Hash (cost=37380.39..37380.39 rows=36639 width=16) (actual time=187.691..187.691 rows=109917 loops=1)

Buckets: 131072 (originally 65536) Batches: 1 (originally 1) Memory Usage: 6177kB

Buffers: shared hit=16522

-> Gather (cost=3447.82..37380.39 rows=36639 width=16) (actual time=15.788..121.575 rows=109917 loops=1)

Workers Planned: 2

Workers Launched: 2

Buffers: shared hit=16522

-> Parallel Bitmap Heap Scan on site_exposure_p1000013 se1 (cost=2447.82..32716.49 rows=15266 width=16) (actual time=5.064..93.457 rows=36639 loops=3)

Heap Blocks: exact=3255

Buffers: shared hit=16522

-> Bitmap Index Scan on site_exposure_p1000013_shape_idx (cost=0.00..2438.66 rows=109917 width=0) (actual time=12.356..12.356 rows=109917 loops=1)

Buffers: shared hit=797

-> Hash (cost=1369.68..1369.68 rows=47174 width=52) (actual time=57.599..57.600 rows=47174 loops=1)

Buckets: 65536 Batches: 1 Memory Usage: 4378kB

Buffers: shared hit=780

-> Seq Scan on account_p1000013 a (cost=0.00..1369.68 rows=47174 width=52) (actual time=0.017..29.184 rows=47174 loops=1)

Filter: (portfolio_id = 1000013)

Buffers: shared hit=780 Planning time: 8.005 ms Execution time: 2721.799 ms

(97 rows)

Time: 2739.492 ms (00:02.739)

Regards,

Virendra

This message is intended only for the use of the addressee and may contain
information that is PRIVILEGED AND CONFIDENTIAL.

If you are not the intended recipient, you are hereby notified that any
dissemination of this communication is strictly prohibited. If you have
received this communication in error, please erase all copies of the message
and its attachments and notify the sender immediately. Thank you.

pgsql-general by date:

From: "Daniel Verite"
Date: 17 December 2018, 18:35:41
Subject: Re: Creating 2D arrays for pg_copy_from, reading tab-delimted textfile that contains comma and double quotes

From: Ron
Date: 17 December 2018, 19:16:06
Subject: Re: conditionally terminate psql script

NL Join vs Merge Join - 5 hours vs 2 seconds - Mailing list pgsql-general

Previous

Next