Thread: NL Join vs Merge Join - 5 hours vs 2 seconds
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)
Recheck Cond: (shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry)
Filter: ((portfolio_id = 1000013) AND _st_intersects(shape, '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry))
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)
Index Cond: (shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry)
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)
Recheck Cond: (shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry)
Filter: ((portfolio_id = 1000013) AND _st_intersects(shape, '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry))
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)
Index Cond: (shape && '0103000020E610000001000000050000006EDDDBF40F285FC03D719130D9532340BEE0DBF4BFCE53C03D719130D9532340BEE0DBF4BFCE53C0B2C127D5E26B42406EDDDBF40F285FC0B2C127D5E26B42406EDDDBF40F285FC03D719130D9532340'::geometry)
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.
"Kumar, Virendra" <Virendra.Kumar@guycarp.com> writes: > We are using Postgers-XL based on PostgreSQL 10.5 on RHEL7. We have an extreme case of one query which running in 4 hour45 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. It looks like what's burning you is bad estimates at these joins: > -> Nested Loop (cost=33681.00..71431.33 rows=1 width=348) (actual time=359.006..926.303rows=37207 loops=3) > Join Filter: (se.account_id = a.account_id) > -> Hash Join (cost=33680.71..71298.94 rows=395 width=300) (actual time=358.953..656.923rows=36828 loops=3) > Hash Cond: ((se.account_id = sh.account_id) AND (se.site_id = sh.site_id)) ... > -> 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) I'm guessing that account_id, site_id, and portfolio_id are all highly correlated, but the planner doesn't know that and thinks the additional conditions will remove way more rows than they actually do. In PG10 and later, you can probably fix that by creating functional-dependency statistics on those pairs of columns. regards, tom lane
Thank you Tom for initial thoughts! I tried query with function dependency statistics but it did not help. I don't see we can create such statistics on tablejoin. Regards, Virendra -----Original Message----- From: Tom Lane [mailto:tgl@sss.pgh.pa.us] Sent: Monday, December 17, 2018 12:02 PM To: Kumar, Virendra Cc: pgsql-general@lists.postgresql.org Subject: Re: NL Join vs Merge Join - 5 hours vs 2 seconds "Kumar, Virendra" <Virendra.Kumar@guycarp.com> writes: > We are using Postgers-XL based on PostgreSQL 10.5 on RHEL7. We have an extreme case of one query which running in 4 hour45 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. It looks like what's burning you is bad estimates at these joins: > -> Nested Loop (cost=33681.00..71431.33 rows=1 width=348) (actual time=359.006..926.303rows=37207 loops=3) > Join Filter: (se.account_id = a.account_id) > -> Hash Join (cost=33680.71..71298.94 rows=395 width=300) (actual time=358.953..656.923rows=36828 loops=3) > Hash Cond: ((se.account_id = sh.account_id) AND (se.site_id = sh.site_id)) ... > -> 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) I'm guessing that account_id, site_id, and portfolio_id are all highly correlated, but the planner doesn't know that and thinks the additional conditions will remove way more rows than they actually do. In PG10 and later, you can probably fix that by creating functional-dependency statistics on those pairs of columns. regards, tom lane ________________________________ 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.
On Tue, 18 Dec 2018 at 09:21, Kumar, Virendra <Virendra.Kumar@guycarp.com> wrote: > I tried query with function dependency statistics but it did not help. I don't see we can create such statistics on tablejoin. There's mention of why this is the case in the docs in [1]: "14.2.2.1.1. Limitations of Functional Dependencies Functional dependencies are currently only applied when considering simple equality conditions that compare columns to constant values. They are not used to improve estimates for equality conditions comparing two columns or comparing a column to an expression, nor for range clauses, LIKE or any other type of condition." [1] https://www.postgresql.org/docs/10/planner-stats.html -- David Rowley http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services