Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1ZtIPJ-0000vf-Ux for pgsql-performance@arkaria.postgresql.org; Mon, 02 Nov 2015 16:56:34 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84) (envelope-from ) id 1ZtIPJ-0005BH-5c for pgsql-performance@arkaria.postgresql.org; Mon, 02 Nov 2015 16:56:33 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84) (envelope-from ) id 1ZtINP-0003Ep-GA for pgsql-performance@postgresql.org; Mon, 02 Nov 2015 16:54:35 +0000 Received: from mail.ocsgmbh.com ([130.180.49.58]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84) (envelope-from ) id 1ZtINL-0000FI-VZ for pgsql-performance@postgresql.org; Mon, 02 Nov 2015 16:54:35 +0000 Received: from [10.80.80.117] (port=33777 helo=EX2k13.ocsnet.local) by mail.ocsgmbh.com with esmtps (TLSv1:AES256-SHA:256) (Exim 4.82_1-5b7a7c0-XX) (envelope-from ) id 1ZtINC-00040g-1u for pgsql-performance@postgresql.org; Mon, 02 Nov 2015 17:54:22 +0100 Received: from EX2K13.ocsnet.local (10.80.80.117) by EX2k13.ocsnet.local (10.80.80.117) with Microsoft SMTP Server (TLS) id 15.0.847.32; Mon, 2 Nov 2015 17:54:22 +0100 Received: from EX2K13.ocsnet.local ([fe80::5995:67ac:bffa:e7bf]) by EX2k13.ocsnet.local ([fe80::5995:67ac:bffa:e7bf%12]) with mapi id 15.00.0847.040; Mon, 2 Nov 2015 17:54:21 +0100 From: Guido Niewerth To: Guido Niewerth , "pgsql-performance@postgresql.org" Subject: Re: Slow query in trigger function Thread-Topic: Slow query in trigger function Thread-Index: AdEVV2md0gPsAGXpQliVPXR/PhjpTgANy4KQ Date: Mon, 2 Nov 2015 16:54:21 +0000 Message-ID: <59f5e6f55a72407bbb521a4b7020c692@EX2k13.ocsnet.local> References: In-Reply-To: Accept-Language: de-DE, en-US Content-Language: de-DE X-MS-Has-Attach: X-MS-TNEF-Correlator: x-originating-ip: [10.80.81.95] x-gfi-smtp-submission: 1 x-gfi-smtp-hellodomain: EX2K13.ocsnet.local x-gfi-smtp-remoteip: 10.80.80.117 Content-Type: multipart/alternative; boundary="_000_59f5e6f55a72407bbb521a4b7020c692EX2k13ocsnetlocal_" MIME-Version: 1.0 X-Pg-Spam-Score: -1.9 (-) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --_000_59f5e6f55a72407bbb521a4b7020c692EX2k13ocsnetlocal_ Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable 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 :=3D timeofday(); IF TG_OP =3D 'UPDATE' THEN IF NOT EXISTS( SELECT key FROM custom_data WHERE key =3D old.key LIMI= T 1 ) THEN DELETE FROM lookup_custom_data_keys WHERE key =3D old.key; END IF; IF NOT EXISTS( SELECT 1 FROM lookup_custom_data_keys WHERE key =3D ne= w.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, st= art ); 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 sca= n where it=B4s 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 WH= ERE key =3D old.key LIMIT 1 ) Result (cost=3D0.09..0.10 rows=3D1 width=3D0) (actual time= =3D5195.667..5195.667 rows=3D1 loops=3D1) Output: (NOT $0) Buffers: shared hit=3D34 read=3D351750 InitPlan 1 (returns $0) -> Limit (cost=3D0.00..0.09 rows=3D1 width=3D0) (actu= al time=3D5195.662..5195.662 rows=3D0 loops=3D1) Output: (1) Buffers: shared hit=3D34 read=3D351750 -> Seq Scan on public.custom_data (cost=3D0.00.= .821325.76 rows=3D9390835 width=3D0) (actual time=3D5195.658..5195.658 rows= =3D0 loops=3D1) Output: 1 Filter: (custom_data.key =3D $15) Buffers: shared hit=3D34 read=3D351750 2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung =BBSELECT NOT EXISTS( = SELECT 1 FROM custom_data WHERE key =3D old.key LIMIT 1 )=AB 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 = =3D old.key Delete on public.lookup_custom_data_keys (cost=3D0.00..38.= 25 rows=3D1 width=3D6) (actual time=3D0.013..0.013 rows=3D0 loops=3D1) Buffers: shared hit=3D2 -> Seq Scan on public.lookup_custom_data_keys (cost=3D0= .00..38.25 rows=3D1 width=3D6) (actual time=3D0.007..0.007 rows=3D1 loops= =3D1) Output: ctid Filter: (lookup_custom_data_keys.key =3D $15) Buffers: shared hit=3D1 2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung =BBDELETE FROM lookup_= custom_data_keys WHERE key =3D old.key=AB 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 =3D new.key LIMIT 1 ) Result (cost=3D38.25..38.26 rows=3D1 width=3D0) (actual ti= me=3D0.004..0.004 rows=3D1 loops=3D1) Output: (NOT $0) Buffers: shared hit=3D1 InitPlan 1 (returns $0) -> Limit (cost=3D0.00..38.25 rows=3D1 width=3D0) (act= ual time=3D0.003..0.003 rows=3D0 loops=3D1) Output: (1) Buffers: shared hit=3D1 -> Seq Scan on public.lookup_custom_data_keys (= cost=3D0.00..38.25 rows=3D1 width=3D0) (actual time=3D0.002..0.002 rows=3D0= loops=3D1) Output: 1 Filter: (lookup_custom_data_keys.key =3D $1= 7) Buffers: shared hit=3D1 2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung =BBSELECT NOT EXISTS( = SELECT 1 FROM lookup_custom_data_keys WHERE key =3D new.key LIMIT 1 )=AB 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) VALUE= S (new.key) Insert on public.lookup_custom_data_keys (cost=3D0.00..0.0= 1 rows=3D1 width=3D0) (actual time=3D0.115..0.115 rows=3D0 loops=3D1) Buffers: shared hit=3D1 -> Result (cost=3D0.00..0.01 rows=3D1 width=3D0) (actua= l time=3D0.001..0.001 rows=3D1 loops=3D1) Output: $17 2015-11-02 17:42:10 CET ZUSAMMENHANG: SQL-Anweisung =BBINSERT INTO lookup_= custom_data_keys (key) VALUES (new.key)=AB PL/pgSQL function "fn_trigger_test" line 11 at SQL-Anweisun= g 2015-11-02 17:42:10 CET LOG: duration: 5200.475 ms plan: Query Text: UPDATE custom_data SET key=3D 'key-2' WHERE key= =3D 'key-1' Update on public.custom_data (cost=3D0.00..15.35 rows=3D1 = width=3D34) (actual time=3D0.369..0.369 rows=3D0 loops=3D1) Buffers: shared hit=3D29 -> Index Scan using idx_custom_data_key on public.custom= _data (cost=3D0.00..15.35 rows=3D1 width=3D34) (actual time=3D0.088..0.090= rows=3D1 loops=3D1) Output: custom_data_id, file_id, user_id, "timestam= p", 'key-2'::text, value, ctid Index Cond: (custom_data.key =3D 'key-1'::text) Buffers: shared hit=3D6 Execution plan of the normal query "SELECT NOT EXISTS( SELECT 1 FROM custom= _data WHERE key=3D'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 WH= ERE key=3D'key-1' LIMIT 1 ); Result (cost=3D15.35..15.36 rows=3D1 width=3D0) (actual ti= me=3D0.047..0.047 rows=3D1 loops=3D1) Output: (NOT $0) Buffers: shared hit=3D6 InitPlan 1 (returns $0) -> Limit (cost=3D0.00..15.35 rows=3D1 width=3D0) (act= ual time=3D0.045..0.045 rows=3D0 loops=3D1) Output: (1) Buffers: shared hit=3D6 -> Index Scan using idx_custom_data_key on publi= c.custom_data (cost=3D0.00..15.35 rows=3D1 width=3D0) (actual time=3D0.043= ..0.043 rows=3D0 loops=3D1) Output: 1 Index Cond: (custom_data.key =3D 'key-1'::t= ext) Buffers: shared hit=3D6 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 --_000_59f5e6f55a72407bbb521a4b7020c692EX2k13ocsnetlocal_ Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable

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

 

CREATE OR REPLACE FUNC= TION public.fn_trigger_test ()

RETURNS trigger AS

$body$

DECLARE

   &nbs= p;            start = TIMESTAMP;

BEGIN

   start := =3D timeofday();

   IF TG_OP = =3D 'UPDATE' THEN

   &nbs= p;  IF NOT EXISTS( SELECT key FROM custom_data WHERE key =3D old.key L= IMIT 1 ) THEN

   &nbs= p;            DELETE FROM= lookup_custom_data_keys WHERE key =3D old.key;

   &nbs= p;  END IF;

   &nbs= p;  IF NOT EXISTS( SELECT 1 FROM lookup_custom_data_keys WHERE key =3D= new.key LIMIT 1 ) THEN

   &nbs= p;            INSERT INTO= lookup_custom_data_keys (key) VALUES (new.key);

   &nbs= p;  END IF;

   END IF;

   RAISE NOT= ICE 'Trigger % ran: %', TG_OP, age( timeofday() ::TIMESTAMP, start );<= /o:p>

   RETURN NU= LL;

END;=

$body$

LANGUAGE 'plpgsql'

VOLATILE

CALLED ON NULL INPUT

SECURITY INVOKER<= /o:p>

COST 100;

 

And this is the execut= ion plan. It looks like it does a slow sequential scan where it=B4s able to= do an index scan:

 

2015-11-02 17:42:10 CE= T LOG:  duration: 5195.673 ms  plan:

   &nbs= p;            Query = Text: SELECT NOT EXISTS( SELECT 1 FROM custom_data WHERE key =3D old.key LI= MIT 1 )

   &nbs= p;            Result=   (cost=3D0.09..0.10 rows=3D1 width=3D0) (actual time=3D5195.667..5195= .667 rows=3D1 loops=3D1)

   &nbs= p;             = Output: (NOT $0)

   &nbs= p;             = Buffers: shared hit=3D34 read=3D351750

   &nbs= p;             = InitPlan 1 (returns $0)

   &nbs= p;             =    ->  Limit  (cost=3D0.00..0.09 rows=3D1 width=3D0)= (actual time=3D5195.662..5195.662 rows=3D0 loops=3D1)

   &nbs= p;             =          Output: (1)

   &nbs= p;             =          Buffers: shared hit=3D34 r= ead=3D351750

   &nbs= p;             =          ->  Seq Scan on pu= blic.custom_data  (cost=3D0.00..821325.76 rows=3D9390835 width=3D0) (a= ctual time=3D5195.658..5195.658 rows=3D0 loops=3D1)

   &nbs= p;             =             &nb= sp;  Output: 1

   &nbs= p;             =             &nb= sp;  Filter: (custom_data.key =3D $15)

   &nbs= p;             =             &nb= sp;  Buffers: shared hit=3D34 read=3D351750

2015-11-02 17:42:10 CE= T ZUSAMMENHANG:  SQL-Anweisung =BBSELECT NOT EXISTS( SELECT 1 FROM cus= tom_data WHERE key =3D old.key LIMIT 1 )=AB

   &nbs= p;            PL/pgS= QL function "fn_trigger_test" line 7 at IF

2015-11-02 17:42:10 CE= T LOG:  duration: 0.014 ms  plan:

   &nbs= p;            Query = Text: DELETE FROM lookup_custom_data_keys WHERE key =3D old.key<= /span>

   &nbs= p;            Delete= on public.lookup_custom_data_keys  (cost=3D0.00..38.25 rows=3D1 width= =3D6) (actual time=3D0.013..0.013 rows=3D0 loops=3D1)

   &nbs= p;             = Buffers: shared hit=3D2

   &nbs= p;             = ->  Seq Scan on public.lookup_custom_data_keys  (cost=3D0.00.= .38.25 rows=3D1 width=3D6) (actual time=3D0.007..0.007 rows=3D1 loops=3D1)<= o:p>

   &nbs= p;             =        Output: ctid

   &nbs= p;             =        Filter: (lookup_custom_data_keys.key = =3D $15)

   &nbs= p;             =        Buffers: shared hit=3D1

2015-11-02 17:42:10 CE= T ZUSAMMENHANG:  SQL-Anweisung =BBDELETE FROM lookup_custom_data_keys = WHERE key =3D old.key=AB

   &nbs= p;            PL/pgS= QL function "fn_trigger_test" line 8 at SQL-Anweisung<= /span>

2015-11-02 17:42:10 CE= T LOG:  duration: 0.005 ms  plan:

   &nbs= p;            Query = Text: SELECT NOT EXISTS( SELECT 1 FROM lookup_custom_data_keys WHERE key = =3D new.key LIMIT 1 )

   &nbs= p;            Result=   (cost=3D38.25..38.26 rows=3D1 width=3D0) (actual time=3D0.004..0.004= rows=3D1 loops=3D1)

   &nbs= p;             = Output: (NOT $0)

   &nbs= p;             = Buffers: shared hit=3D1

   &nbs= p;             = InitPlan 1 (returns $0)

   &nbs= p;             =    ->  Limit  (cost=3D0.00..38.25 rows=3D1 width=3D0= ) (actual time=3D0.003..0.003 rows=3D0 loops=3D1)

   &nbs= p;             =          Output: (1)

   &nbs= p;             =          Buffers: shared hit=3D1

   &nbs= p;             =          ->  Seq Scan on pu= blic.lookup_custom_data_keys  (cost=3D0.00..38.25 rows=3D1 width=3D0) = (actual time=3D0.002..0.002 rows=3D0 loops=3D1)

   &nbs= p;             =             &nb= sp;  Output: 1

   &nbs= p;             =             &nb= sp;  Filter: (lookup_custom_data_keys.key =3D $17)

   &nbs= p;             =             &nb= sp;  Buffers: shared hit=3D1

2015-11-02 17:42:10 CE= T ZUSAMMENHANG:  SQL-Anweisung =BBSELECT NOT EXISTS( SELECT 1 FROM loo= kup_custom_data_keys WHERE key =3D new.key LIMIT 1 )=AB

   &nbs= p;            PL/pgS= QL function "fn_trigger_test" line 10 at IF

2015-11-02 17:42:10 CE= T LOG:  duration: 0.116 ms  plan:

   &nbs= p;            Query = Text: INSERT INTO lookup_custom_data_keys (key) VALUES (new.key)=

   &nbs= p;            Insert= on public.lookup_custom_data_keys  (cost=3D0.00..0.01 rows=3D1 width= =3D0) (actual time=3D0.115..0.115 rows=3D0 loops=3D1)

   &nbs= p;             = Buffers: shared hit=3D1

   &nbs= p;             = ->  Result  (cost=3D0.00..0.01 rows=3D1 width=3D0) (actual ti= me=3D0.001..0.001 rows=3D1 loops=3D1)

   &nbs= p;             =        Output: $17

2015-11-02 17:42:10 CE= T ZUSAMMENHANG:  SQL-Anweisung =BBINSERT INTO lookup_custom_data_keys = (key) VALUES (new.key)=AB

   &nbs= p;            PL/pgS= QL function "fn_trigger_test" line 11 at SQL-Anweisung=

2015-11-02 17:42:10 CE= T LOG:  duration: 5200.475 ms  plan:

   &nbs= p;            Query = Text: UPDATE custom_data SET key=3D 'key-2' WHERE key =3D 'key-1'

   &nbs= p;            Update= on public.custom_data  (cost=3D0.00..15.35 rows=3D1 width=3D34) (actu= al time=3D0.369..0.369 rows=3D0 loops=3D1)

   &nbs= p;             = Buffers: shared hit=3D29

   &nbs= p;             = ->  Index Scan using idx_custom_data_key on public.custom_data&nbs= p; (cost=3D0.00..15.35 rows=3D1 width=3D34) (actual time=3D0.088..0.090 row= s=3D1 loops=3D1)

   &nbs= p;             =        Output: custom_data_id, file_id, user_= id, "timestamp", 'key-2'::text, value, ctid

   &nbs= p;             =        Index Cond: (custom_data.key =3D 'key-= 1'::text)

   &nbs= p;             =        Buffers: shared hit=3D6

 

 

 

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

 

2015-11-02 17:44:28 CE= T LOG:  duration: 0.052 ms  plan:

   &nbs= p;            Query = Text: SELECT NOT EXISTS( SELECT 1 FROM custom_data WHERE key=3D'key-1' LIMI= T 1 );

   &nbs= p;            Result=   (cost=3D15.35..15.36 rows=3D1 width=3D0) (actual time=3D0.047..0.047= rows=3D1 loops=3D1)

   &nbs= p;             = Output: (NOT $0)

   &nbs= p;             = Buffers: shared hit=3D6

   &nbs= p;             = InitPlan 1 (returns $0)

   &nbs= p;             =    ->  Limit  (cost=3D0.00..15.35 rows=3D1 width=3D0= ) (actual time=3D0.045..0.045 rows=3D0 loops=3D1)

   &nbs= p;             =          Output: (1)

   &nbs= p;             =          Buffers: shared hit=3D6

   &nbs= p;             =          ->  Index Scan usi= ng idx_custom_data_key on public.custom_data  (cost=3D0.00..15.35 rows= =3D1 width=3D0) (actual time=3D0.043..0.043 rows=3D0 loops=3D1)<= /span>

   &nbs= p;             =             &nb= sp;  Output: 1

   &nbs= p;             =             &nb= sp;  Index Cond: (custom_data.key =3D 'key-1'::text)=

   &nbs= p;             =              &n= bsp; Buffers: shared hit=3D6

 

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 9562= 2-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


--_000_59f5e6f55a72407bbb521a4b7020c692EX2k13ocsnetlocal_--