Re: Very poor performance with Nested Loop Anti Join - Mailing list pgsql-performance
På mandag 01. august 2016 kl. 15:33:04, skrev Andreas Joseph Krogh <andreas@visena.com>:
I have this schema:CREATE TABLE onp_crm_person( id serial PRIMARY KEY, onp_user_id bigint references onp_user(id) deferrable initially deferred, is_resource boolean not null default false, UNIQUE(onp_user_id) ); CREATE TABLE onp_crm_activity_log( id bigserial PRIMARY KEY, relation_id integer REFERENCES onp_crm_relation(entity_id), logged_for int references onp_crm_person(onp_user_id), duration bigint ); CREATE TABLE onp_crm_invoice( entity_id bigint PRIMARY KEY REFERENCES onp_crm_entity(entity_id), status_key VARCHAR NOT NULL, credit_against bigint REFERENCES onp_crm_invoice(entity_id), sent_date DATE, UNIQUE(credit_against) deferrable INITIALLY DEFERRED -- invoice_print_template_id is added after creation of origo_invoice_print_template ); CREATE TABLE onp_crm_invoice_line ( id SERIAL PRIMARY KEY, invoice_id INTEGER NOT NULL REFERENCES onp_crm_invoice (entity_id) ); CREATE TABLE onp_crm_calendarentry_invoice_membership( invoice_line_id INTEGER NOT NULL REFERENCES onp_crm_invoice_line(id) ON DELETE CASCADE, calendar_entry_id INTEGER NOT NULL REFERENCES onp_crm_activity_log(id), unique(invoice_line_id, calendar_entry_id) DEFERRABLE INITIALLY DEFERRED );This query performs terribly slow ( ~26 minutes, 1561346.597ms):explain analyze SELECT log.relation_id as company_id , sum(log.duration) AS duration FROM onp_crm_activity_log log JOIN onp_crm_person logfor ON logfor.onp_user_id = log.logged_for AND logfor.is_resource = FALSE WHERE 1 = 1 -- Filter out already invoiced before 2016-06-27 AND NOT EXISTS( SELECT * FROM onp_crm_calendarentry_invoice_membership cem JOIN onp_crm_invoice_line il ON cem.invoice_line_id = il.id JOIN onp_crm_invoice inv ON il.invoice_id = inv.entity_id WHERE cem.calendar_entry_id = log.id AND inv.status_key = 'INVOICE_STATUS_INVOICED' AND inv.sent_date <= '2016-06-27' AND NOT EXISTS( SELECT * FROM onp_crm_invoice creditnote WHERE il.invoice_id = creditnote.credit_against AND creditnote.status_key = 'INVOICE_STATUS_INVOICED' AND creditnote.sent_date <= '2016-06-27' ) ) GROUP BY log.relation_id ;Explain output:QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=13778.63..13796.39 rows=1421 width=12) (actual time=1561343.861..1561344.042 rows=724 loops=1)
Group Key: log.relation_id
-> Nested Loop Anti Join (cost=741.35..13768.63 rows=2000 width=12) (actual time=471.973..1561221.929 rows=96095 loops=1)
Join Filter: (cem.calendar_entry_id = log.id)
Rows Removed by Join Filter: 11895758618
-> Hash Join (cost=86.56..9729.03 rows=2000 width=20) (actual time=0.170..668.911 rows=181644 loops=1)
Hash Cond: (log.logged_for = logfor.onp_user_id)
-> Seq Scan on onp_crm_activity_log log (cost=0.00..8930.98 rows=184398 width=24) (actual time=0.007..538.893 rows=182378 loops=1)
-> Hash (cost=39.46..39.46 rows=3768 width=8) (actual time=0.126..0.126 rows=36 loops=1)
Buckets: 4096 Batches: 1 Memory Usage: 34kB
-> Bitmap Heap Scan on onp_crm_person logfor (cost=3.69..39.46 rows=3768 width=8) (actual time=0.040..0.106 rows=36 loops=1)
Recheck Cond: (onp_user_id IS NOT NULL)
Filter: (NOT is_resource)
Rows Removed by Filter: 5
Heap Blocks: exact=10
-> Bitmap Index Scan on onp_crm_person_onp_id_idx (cost=0.00..2.75 rows=41 width=0) (actual time=0.019..0.019 rows=41 loops=1)
-> Materialize (cost=654.79..4009.60 rows=1 width=4) (actual time=0.000..2.829 rows=65490 loops=181644)
-> Nested Loop (cost=654.79..4009.59 rows=1 width=4) (actual time=9.056..386.835 rows=85668 loops=1)
-> Nested Loop (cost=654.50..4009.27 rows=1 width=8) (actual time=9.046..165.280 rows=88151 loops=1)
-> Hash Anti Join (cost=654.21..4008.72 rows=1 width=8) (actual time=9.016..40.672 rows=76174 loops=1)
Hash Cond: (il.invoice_id = creditnote.credit_against)
-> Seq Scan on onp_crm_invoice_line il (cost=0.00..3062.01 rows=78001 width=8) (actual time=0.005..11.259 rows=78614 loops=1)
-> Hash (cost=510.56..510.56 rows=11492 width=8) (actual time=8.940..8.940 rows=372 loops=1)
Buckets: 16384 Batches: 1 Memory Usage: 143kB
-> Seq Scan on onp_crm_invoice creditnote (cost=0.00..510.56 rows=11492 width=8) (actual time=0.014..7.882 rows=11507 loops=1)
Filter: ((sent_date <= '2016-06-27'::date) AND ((status_key)::text = 'INVOICE_STATUS_INVOICED'::text))
Rows Removed by Filter: 149
-> Index Only Scan using onp_crm_calendarentry_invoice_invoice_line_id_calendar_entr_key on onp_crm_calendarentry_invoice_membership cem (cost=0.29..0.45 rows=9 width=8) (actual time=0.001..0.001 rows=1 loops=76174)
Index Cond: (invoice_line_id = il.id)
Heap Fetches: 4371
-> Index Scan using onp_crm_invoice_pkey on onp_crm_invoice inv (cost=0.29..0.31 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=88151)
Index Cond: (entity_id = il.invoice_id)
Filter: ((sent_date <= '2016-06-27'::date) AND ((status_key)::text = 'INVOICE_STATUS_INVOICED'::text))
Rows Removed by Filter: 0
Planning time: 3.307 ms
Execution time: 1561346.597 ms
(36 rows)
Here is with set enable_nestloop to false;QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=15936.07..15953.83 rows=1421 width=12) (actual time=337.878..338.045 rows=724 loops=1)
Group Key: log.relation_id
-> Hash Anti Join (cost=6258.35..15926.07 rows=2000 width=12) (actual time=139.976..317.402 rows=96097 loops=1)
Hash Cond: (log.id = cem.calendar_entry_id)
-> Hash Join (cost=86.56..9729.03 rows=2000 width=20) (actual time=0.164..132.935 rows=181646 loops=1)
Hash Cond: (log.logged_for = logfor.onp_user_id)
-> Seq Scan on onp_crm_activity_log log (cost=0.00..8930.98 rows=184398 width=24) (actual time=0.006..89.170 rows=182380 loops=1)
-> Hash (cost=39.46..39.46 rows=3768 width=8) (actual time=0.118..0.118 rows=36 loops=1)
Buckets: 4096 Batches: 1 Memory Usage: 34kB
-> Bitmap Heap Scan on onp_crm_person logfor (cost=3.69..39.46 rows=3768 width=8) (actual time=0.037..0.101 rows=36 loops=1)
Recheck Cond: (onp_user_id IS NOT NULL)
Filter: (NOT is_resource)
Rows Removed by Filter: 5
Heap Blocks: exact=10
-> Bitmap Index Scan on onp_crm_person_onp_id_idx (cost=0.00..2.75 rows=41 width=0) (actual time=0.017..0.017 rows=41 loops=1)
-> Hash (cost=6171.78..6171.78 rows=1 width=4) (actual time=139.779..139.779 rows=85668 loops=1)
Buckets: 131072 (originally 1024) Batches: 1 (originally 1) Memory Usage: 4036kB
-> Hash Join (cost=4562.41..6171.78 rows=1 width=4) (actual time=92.471..125.417 rows=85668 loops=1)
Hash Cond: (cem.invoice_line_id = il.id)
-> Seq Scan on onp_crm_calendarentry_invoice_membership cem (cost=0.00..1278.44 rows=88244 width=8) (actual time=0.005..7.941 rows=88734 loops=1)
-> Hash (cost=4562.40..4562.40 rows=1 width=4) (actual time=92.444..92.444 rows=75570 loops=1)
Buckets: 131072 (originally 1024) Batches: 1 (originally 1) Memory Usage: 3681kB
-> Hash Join (cost=4008.74..4562.40 rows=1 width=4) (actual time=61.797..79.981 rows=75570 loops=1)
Hash Cond: (inv.entity_id = il.invoice_id)
-> Seq Scan on onp_crm_invoice inv (cost=0.00..510.56 rows=11492 width=8) (actual time=0.027..4.489 rows=11507 loops=1)
Filter: ((sent_date <= '2016-06-27'::date) AND ((status_key)::text = 'INVOICE_STATUS_INVOICED'::text))
Rows Removed by Filter: 151
-> Hash (cost=4008.72..4008.72 rows=1 width=8) (actual time=61.751..61.751 rows=76182 loops=1)
Buckets: 131072 (originally 1024) Batches: 1 (originally 1) Memory Usage: 4000kB
-> Hash Anti Join (cost=654.21..4008.72 rows=1 width=8) (actual time=12.568..47.911 rows=76182 loops=1)
Hash Cond: (il.invoice_id = creditnote.credit_against)
-> Seq Scan on onp_crm_invoice_line il (cost=0.00..3062.01 rows=78001 width=8) (actual time=0.008..12.476 rows=78622 loops=1)
-> Hash (cost=510.56..510.56 rows=11492 width=8) (actual time=12.477..12.477 rows=372 loops=1)
Buckets: 16384 Batches: 1 Memory Usage: 143kB
-> Seq Scan on onp_crm_invoice creditnote (cost=0.00..510.56 rows=11492 width=8) (actual time=0.008..10.963 rows=11507 loops=1)
Filter: ((sent_date <= '2016-06-27'::date) AND ((status_key)::text = 'INVOICE_STATUS_INVOICED'::text))
Rows Removed by Filter: 151
Planning time: 3.510 ms
Execution time: 338.349 ms
(39 rows)
So my question is is there something I can do to make PG favor a Hash Anti Join instead of a Nested Loop Anti Join (which I assume is the problem)?Can the nested NOT EXISTS be re-written to be more performant?Thanks.
If I leave out the JOIN with onp_crm_person the query-plan is also much more efficient:
explain analyze
SELECT
log.relation_id as company_id , sum(log.duration) AS duration
FROM onp_crm_activity_log log
WHERE 1 = 1
-- Filter out already invoiced
AND NOT EXISTS( SELECT * FROM onp_crm_calendarentry_invoice_membership cem JOIN onp_crm_invoice_line il ON cem.invoice_line_id = il.id JOIN onp_crm_invoice inv ON il.invoice_id = inv.entity_id WHERE cem.calendar_entry_id = log.id AND inv.status_key = 'INVOICE_STATUS_INVOICED'
AND inv.sent_date <= '2016-06-27'
AND NOT EXISTS( SELECT * FROM onp_crm_invoice creditnote WHERE il.invoice_id = creditnote.credit_against AND creditnote.status_key = 'INVOICE_STATUS_INVOICED'
AND creditnote.sent_date <= '2016-06-27'
)
)
GROUP BY
log.relation_id
;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=16192.30..16210.07 rows=1421 width=12) (actual time=562.978..563.144 rows=724 loops=1) Group Key: log.relation_id -> Hash Anti Join (cost=4009.60..15270.19 rows=184423 width=12) (actual time=422.215..542.871 rows=96712 loops=1) Hash Cond: (log.id = cem.calendar_entry_id) -> Seq Scan on onp_crm_activity_log log (cost=0.00..8932.24 rows=184424 width=20) (actual time=0.007..83.262 rows=182380 loops=1) -> Hash (cost=4009.59..4009.59 rows=1 width=4) (actual time=422.178..422.178 rows=85668 loops=1) Buckets: 131072 (originally 1024) Batches: 1 (originally 1) Memory Usage: 4036kB -> Nested Loop (cost=654.79..4009.59 rows=1 width=4) (actual time=12.210..397.383 rows=85668 loops=1) -> Nested Loop (cost=654.50..4009.27 rows=1 width=8) (actual time=12.189..173.380 rows=88201 loops=1) -> Hash Anti Join (cost=654.21..4008.72 rows=1 width=8) (actual time=12.099..47.757 rows=76197 loops=1) Hash Cond: (il.invoice_id = creditnote.credit_against) -> Seq Scan on onp_crm_invoice_line il (cost=0.00..3062.01 rows=78001 width=8) (actual time=0.009..13.797 rows=78637 loops=1) -> Hash (cost=510.56..510.56 rows=11492 width=8) (actual time=12.012..12.012 rows=372 loops=1) Buckets: 16384 Batches: 1 Memory Usage: 143kB -> Seq Scan on onp_crm_invoice creditnote (cost=0.00..510.56 rows=11492 width=8) (actual time=0.026..10.564 rows=11507 loops=1) Filter: ((sent_date <= '2016-06-27'::date) AND ((status_key)::text = 'INVOICE_STATUS_INVOICED'::text)) Rows Removed by Filter: 155
-> Index Only Scan using onp_crm_calendarentry_invoice_invoice_line_id_calendar_entr_key on onp_crm_calendarentry_invoice_membership cem (cost=0.29..0.45 rows=9 width=8) (actual time=0.001..0.001 rows=1 loops=76197) Index Cond: (invoice_line_id = il.id) Heap Fetches: 4421
-> Index Scan using onp_crm_invoice_pkey on onp_crm_invoice inv (cost=0.29..0.31 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=88201) Index Cond: (entity_id = il.invoice_id) Filter: ((sent_date <= '2016-06-27'::date) AND ((status_key)::text = 'INVOICE_STATUS_INVOICED'::text)) Rows Removed by Filter: 0
Planning time: 2.763 ms Execution time: 563.403 ms
(26 rows)
But of course I cannot do that... It's just for information...
--
Andreas Joseph Krogh
CTO / Partner - Visena AS
Mobile: +47 909 56 963
Attachment
pgsql-performance by date: