Re: Slow query in trigger function

I needed to set up the trigger function again, so here it is:

CREATE OR REPLACE FUNCTION public.fn_trigger_test ()
RETURNS trigger AS
$body$
DECLARE
start TIMESTAMP;
BEGIN
start := timeofday();
IF TG_OP = 'UPDATE' THEN
IF NOT EXISTS( SELECT key FROM custom_data WHERE key = old.key LIMIT 1 ) THEN
DELETE FROM lookup_custom_data_keys WHERE key = old.key;
END IF;
IF NOT EXISTS( SELECT 1 FROM lookup_custom_data_keys WHERE key = new.key LIMIT 1 ) THEN
INSERT INTO lookup_custom_data_keys (key) VALUES (new.key);
END IF;
END IF;
RAISE NOTICE 'Trigger % ran: %', TG_OP, age( timeofday() ::TIMESTAMP, start );
RETURN NULL;
END;
$body$
LANGUAGE 'plpgsql'
VOLATILE
CALLED ON NULL INPUT
SECURITY INVOKER
COST 100;

And this is the execution plan. It looks like it does a slow sequential scan where it´s able to do an index scan:

2015-11-02 17:42:10 CET LOG: duration: 5195.673 ms plan:
Query Text: SELECT NOT EXISTS( SELECT 1 FROM custom_data WHERE key = old.key LIMIT 1 )
Result (cost=0.09..0.10 rows=1 width=0) (actual time=5195.667..5195.667 rows=1 loops=1)
Output: (NOT $0)
Buffers: shared hit=34 read=351750
InitPlan 1 (returns $0)
-> Limit (cost=0.00..0.09 rows=1 width=0) (actual time=5195.662..5195.662 rows=0 loops=1)
Output: (1)
Buffers: shared hit=34 read=351750
-> Seq Scan on public.custom_data (cost=0.00..821325.76 rows=9390835 width=0) (actual time=5195.658..5195.658 rows=0 loops=1)
Output: 1
Filter: (custom_data.key = $15)
Buffers: shared hit=34 read=351750
2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung »SELECT NOT EXISTS( SELECT 1 FROM custom_data WHERE key = old.key LIMIT 1 )«
PL/pgSQL function "fn_trigger_test" line 7 at IF
2015-11-02 17:42:10 CET LOG: duration: 0.014 ms plan:
Query Text: DELETE FROM lookup_custom_data_keys WHERE key = old.key
Delete on public.lookup_custom_data_keys (cost=0.00..38.25 rows=1 width=6) (actual time=0.013..0.013 rows=0 loops=1)
Buffers: shared hit=2
-> Seq Scan on public.lookup_custom_data_keys (cost=0.00..38.25 rows=1 width=6) (actual time=0.007..0.007 rows=1 loops=1)
Output: ctid
Filter: (lookup_custom_data_keys.key = $15)
Buffers: shared hit=1
2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung »DELETE FROM lookup_custom_data_keys WHERE key = old.key«
PL/pgSQL function "fn_trigger_test" line 8 at SQL-Anweisung
2015-11-02 17:42:10 CET LOG: duration: 0.005 ms plan:
Query Text: SELECT NOT EXISTS( SELECT 1 FROM lookup_custom_data_keys WHERE key = new.key LIMIT 1 )
Result (cost=38.25..38.26 rows=1 width=0) (actual time=0.004..0.004 rows=1 loops=1)
Output: (NOT $0)
Buffers: shared hit=1
InitPlan 1 (returns $0)
-> Limit (cost=0.00..38.25 rows=1 width=0) (actual time=0.003..0.003 rows=0 loops=1)
Output: (1)
Buffers: shared hit=1
-> Seq Scan on public.lookup_custom_data_keys (cost=0.00..38.25 rows=1 width=0) (actual time=0.002..0.002 rows=0 loops=1)
Output: 1
Filter: (lookup_custom_data_keys.key = $17)
Buffers: shared hit=1
2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung »SELECT NOT EXISTS( SELECT 1 FROM lookup_custom_data_keys WHERE key = new.key LIMIT 1 )«
PL/pgSQL function "fn_trigger_test" line 10 at IF
2015-11-02 17:42:10 CET LOG: duration: 0.116 ms plan:
Query Text: INSERT INTO lookup_custom_data_keys (key) VALUES (new.key)
Insert on public.lookup_custom_data_keys (cost=0.00..0.01 rows=1 width=0) (actual time=0.115..0.115 rows=0 loops=1)
Buffers: shared hit=1
-> Result (cost=0.00..0.01 rows=1 width=0) (actual time=0.001..0.001 rows=1 loops=1)
Output: $17
2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung »INSERT INTO lookup_custom_data_keys (key) VALUES (new.key)«
PL/pgSQL function "fn_trigger_test" line 11 at SQL-Anweisung
2015-11-02 17:42:10 CET LOG: duration: 5200.475 ms plan:
Query Text: UPDATE custom_data SET key= 'key-2' WHERE key = 'key-1'
Update on public.custom_data (cost=0.00..15.35 rows=1 width=34) (actual time=0.369..0.369 rows=0 loops=1)
Buffers: shared hit=29
-> Index Scan using idx_custom_data_key on public.custom_data (cost=0.00..15.35 rows=1 width=34) (actual time=0.088..0.090 rows=1 loops=1)
Output: custom_data_id, file_id, user_id, "timestamp", 'key-2'::text, value, ctid
Index Cond: (custom_data.key = 'key-1'::text)
Buffers: shared hit=6

Execution plan of the normal query "SELECT NOT EXISTS( SELECT 1 FROM custom_data WHERE key='key-1' LIMIT 1 );":

2015-11-02 17:44:28 CET LOG: duration: 0.052 ms plan:
Query Text: SELECT NOT EXISTS( SELECT 1 FROM custom_data WHERE key='key-1' LIMIT 1 );
Result (cost=15.35..15.36 rows=1 width=0) (actual time=0.047..0.047 rows=1 loops=1)
Output: (NOT $0)
Buffers: shared hit=6
InitPlan 1 (returns $0)
-> Limit (cost=0.00..15.35 rows=1 width=0) (actual time=0.045..0.045 rows=0 loops=1)
Output: (1)
Buffers: shared hit=6
-> Index Scan using idx_custom_data_key on public.custom_data (cost=0.00..15.35 rows=1 width=0) (actual time=0.043..0.043 rows=0 loops=1)
Output: 1
Index Cond: (custom_data.key = 'key-1'::text)
Buffers: shared hit=6

Guido Niewerth

25 years inspired synergy
OCS Optical Control Systems GmbH
Wullener Feld 24
58454 Witten
Germany

Tel: +49 (0) 2302 95622-0
Fax: +49 (0) 2302 95622-33
Email: gniewerth(at)ocsgmbh(dot)com
Web: http://www.ocsgmbh.com

HRB 8442 (Bochum) | VAT-ID: DE 124 084 990
Directors: Hans Gloeckler, Fatah Najaf, Merdan Sariboga