Re: Slow query in trigger function - Mailing list pgsql-performance

From Guido Niewerth
Subject Re: Slow query in trigger function
Date
Msg-id 59f5e6f55a72407bbb521a4b7020c692@EX2k13.ocsnet.local
Whole thread Raw
In response to Slow query in trigger function  (Guido Niewerth <gniewerth@ocsgmbh.com>)
Responses Re: Slow query in trigger function  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-performance

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@ocsgmbh.com
Web: http://www.ocsgmbh.com

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


pgsql-performance by date:

Previous
From: Tom Lane
Date:
Subject: Re: Slow query in trigger function
Next
From: Tom Lane
Date:
Subject: Re: Slow query in trigger function