Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1ZtCBM-0002ea-Mt for pgsql-performance@arkaria.postgresql.org; Mon, 02 Nov 2015 10:17:44 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84) (envelope-from ) id 1ZtCBM-0004kU-15 for pgsql-performance@arkaria.postgresql.org; Mon, 02 Nov 2015 10:17:44 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84) (envelope-from ) id 1ZtC9g-0002ur-3R for pgsql-performance@postgresql.org; Mon, 02 Nov 2015 10:16:00 +0000 Received: from mail.ocsgmbh.com ([130.180.49.58]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84) (envelope-from ) id 1ZtC9Y-0005O0-Em for pgsql-performance@postgresql.org; Mon, 02 Nov 2015 10:15:58 +0000 Received: from [10.80.80.117] (port=15664 helo=EX2k13.ocsnet.local) by mail.ocsgmbh.com with esmtps (TLSv1:AES256-SHA:256) (Exim 4.82_1-5b7a7c0-XX) (envelope-from ) id 1ZtC9P-0007zc-0F for pgsql-performance@postgresql.org; Mon, 02 Nov 2015 11:15:43 +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 11:15:42 +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 11:15:35 +0100 From: Guido Niewerth To: "pgsql-performance@postgresql.org" Subject: Slow query in trigger function Thread-Topic: Slow query in trigger function Thread-Index: AdEVV2md0gPsAGXpQliVPXR/PhjpTg== Date: Mon, 2 Nov 2015 10:15:35 +0000 Message-ID: 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_d9752446b5164156836d9bb97bacfe58EX2k13ocsnetlocal_" 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_d9752446b5164156836d9bb97bacfe58EX2k13ocsnetlocal_ Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable Hello, I=B4ve got a table custom_data which essentially contains a number of key/v= alue pairs. This table holds a large number (about 40M) of records and I ne= ed the distinct keys and values for some reasons. Selecting those distinct = data takes a couple of seconds, so I decided to maintain a separate lookup = table for both the key and value data. The lookup tables are maintained by = a trigger that reacts on inserts/updates/deletes on the original table. Whi= le checking the correctness of my trigger function I noticed that the SQL q= uery in the trigger function is surprisingly slow, taking about 5-6 seconds= . When I ran the SQL query outside the trigger function it showed the expec= ted performance and returned in a couple of milliseconds. Though the origin= al table is very large it holds only a small number of distinct key / value= values: SELECT DISTINCT key FROM custom_data; >> 12 rows returned SELECT DISTINCT value FROM custom_data; >> 13 rows returned Here are the relveant information (function body of the trigger function re= duced to show the behaviour): PostgreSQL Version: PostgreSQL 9.1.13, compiled by Visual C++ build 1500, 64-bit OS Version: Windows 7 64bit Scenario to reproduce the behaviour: EMS Solution SQL Manager: SQL Editor used to run SQL commands from an edito= r Server configuration: name current_setting = source DateStyle ISO, DMY = session default_text_search_config pg_catalog.german co= nfiguration file effective_cache_size 8GB = configuration file lc_messages German_Germany.1252 = configuration file lc_monetary German_Germany.1252 = configuration file lc_numeric German_Germany.1252 = configuration file lc_time German_Germany.1252 = configuration file listen_addresses * = configuration file log_destination stderr = configuration file log_line_prefix %t = configuration file log_timezone CET = environment variable logging_collector on = configuration file max_connections 100 = configuration file max_stack_depth 2MB = environment variable port 5432 = configuration file shared_buffers 4GB = configuration file statement_timeout 0 = session TimeZone CET = environment variable work_mem 64MB = configuration file custom_data table definition: CREATE TABLE public.custom_data ( custom_data_id SERIAL, file_id INTEGER DEFAULT 0 NOT NULL, user_id INTEGER DEFAULT 0 NOT NULL, "timestamp" TIMESTAMP(0) WITHOUT TIME ZONE DEFAULT '1970-01-01 00:00:00':= :timestamp without time zone NOT NULL, key TEXT DEFAULT ''::text NOT NULL, value TEXT DEFAULT ''::text NOT NULL, CONSTRAINT pkey_custom_data PRIMARY KEY(custom_data_id), ) WITHOUT OIDS; CREATE INDEX idx_custom_data_key ON public.custom_data USING btree (key); CREATE INDEX idx_custom_data_value ON public.custom_data USING btree (valu= e); CREATE TRIGGER on_custom_data_changed AFTER INSERT OR UPDATE OR DELETE ON public.custom_data FOR EACH ROW EXECUTE PROCEDURE public.on_change_custom_data(); CREATE OR REPLACE FUNCTION public.on_change_custom_data () RETURNS trigger AS $body$ BEGIN IF TG_OP =3D 'UPDATE' THEN RAISE NOTICE 'Check custom data key start : %', timeofday(); IF NOT EXISTS (SELECT 1 FROM custom_data WHERE key =3D OLD.key ) THEN END IF; RAISE NOTICE 'Check custom data key end : %', timeofday(); END IF; RETURN NULL; END; $body$ LANGUAGE 'plpgsql' VOLATILE CALLED ON NULL INPUT SECURITY INVOKER COST 100; postgreSQL log: HINWEIS: Check custom data key start : Fri Oct 30 11:56:41.785000 2015 CE= T << start of IF NOT EXIST (...) HINWEIS: Check custom data key end : Fri Oct 30 11:56:47.145000 2015 CE= T << end of IF NOT EXISTS (...) : ~5.4 seconds Query OK, 1 rows affected (5,367 sec) Same query run in SQL editor: SELECT 1 FROM custom_data WHERE key=3D'key-1' 1 rows returned (16 ms) As you can see there=B4s a huge runtime difference between the select query= used in the trigger function and the one run from the SQL editor. 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_d9752446b5164156836d9bb97bacfe58EX2k13ocsnetlocal_ Content-Type: text/html; charset="iso-8859-1" Content-Transfer-Encoding: quoted-printable

Hello,

 

I=B4ve got a table custom_data which essentially con= tains a number of key/value pairs. This table holds a large number (about 4= 0M) of records and I need the distinct keys and values for some reasons. Se= lecting those distinct data takes a couple of seconds, so I decided to maintain a separate lookup table for bo= th the key and value data. The lookup tables are maintained by a trigger th= at reacts on inserts/updates/deletes on the original table. While checking = the correctness of my trigger function I noticed that the SQL query in the trigger function is surprisingly slow,= taking about 5-6 seconds. When I ran the SQL query outside the trigger fun= ction it showed the expected performance and returned in a couple of millis= econds. Though the original table is very large it holds only a small number of distinct key / value values:=

 

SELECT DISTINCT key FROM custom_data;

>> 12 rows returned

 

SELECT DISTINCT value FROM custom_data;

>> 13 rows returned

 

 

Here are the relveant information (function body of = the trigger function reduced to show the behaviour):

 

PostgreSQL Version:

PostgreSQL 9.1.13, compiled by Visual C++ bu= ild 1500, 64-bit

 

OS Version:

Windows 7 64bit

 

Scenario to reproduce the behaviour:

EMS Solution SQL Manager: SQL Editor used to run SQL= commands from an editor

 

Server configuration:

name         = ;             &= nbsp;           &nbs= p;            &= nbsp;   current_setting       =              &n= bsp;          source

DateStyle       &= nbsp;            &nb= sp;            =           ISO, DMY  =              &n= bsp;            = ;            &n= bsp;  session

default_text_search_config    &n= bsp; pg_catalog.german         &nbs= p;            &= nbsp; configuration file

effective_cache_size      &= nbsp;           &nbs= p; 8GB            &n= bsp;            = ;            &n= bsp;            = ;    configuration file

lc_messages       &nbs= p;            &= nbsp;           &nbs= p;    German_Germany.1252      = ;        configuration file

lc_monetary       &nbs= p;            &= nbsp;           &nbs= p;    German_Germany.1252      = ;        configuration file

lc_numeric       =              &n= bsp;            = ;       German_Germany.1252   =            configuration = file

lc_time        &n= bsp;            = ;            &n= bsp;            = ;  German_Germany.1252        =       configuration file

listen_addresses      =              &n= bsp;         *   &nb= sp;             = ;            &n= bsp;            = ;            &n= bsp;     configuration file

log_destination      &= nbsp;            &nb= sp;           stderr = ;             &= nbsp;           &nbs= p;            &= nbsp;          configuration f= ile

log_line_prefix       =             &nb= sp;            %t&nb= sp;             = ;             &= nbsp;           &nbs= p;            &= nbsp;    configuration file

log_timezone       &nb= sp;            =             &nb= sp; CET            &= nbsp;            &nb= sp;            =             &nb= sp;    environment variable

logging_collector      = ;             &= nbsp;         on   &= nbsp;            &nb= sp;            =             &nb= sp;            =    configuration file

max_connections      &= nbsp;            &nb= sp;       100     &n= bsp;            &nbs= p;            &= nbsp;           &nbs= p;            config= uration file

max_stack_depth      &= nbsp;            &nb= sp;      2MB       &= nbsp;           &nbs= p;            &= nbsp;           &nbs= p;        environment variable

port         = ;            &n= bsp;            = ;            &n= bsp;       5432     =             &n= bsp;            = ;            &n= bsp;         configuration file

shared_buffers      &n= bsp;            &nbs= p;           4GB &nb= sp;             = ;            &n= bsp;            = ;            &n= bsp; configuration file

statement_timeout      = ;             &= nbsp;   0         &n= bsp;            &nbs= p;            &= nbsp;           &nbs= p;            sessio= n

TimeZone       &n= bsp;            &nbs= p;            &= nbsp;        CET    =              &n= bsp;            = ;            &n= bsp;            envi= ronment variable

work_mem        &= nbsp;           &nbs= p;            &= nbsp;     64MB       &nbs= p;            &= nbsp;           &nbs= p;            &= nbsp;     configuration file

 

custom_data table definition:

CREATE TABLE public.custom_data (

  custom_data_id SERIAL,

  file_id INTEGER DEFAULT 0 NOT NULL,

  user_id INTEGER DEFAULT 0 NOT NULL,

  "timestamp" TIMESTAMP(0) WITHO= UT TIME ZONE DEFAULT '1970-01-01 00:00:00'::timestamp without time zone NOT= NULL,

  key TEXT DEFAULT ''::text NOT NULL,

  value TEXT DEFAULT ''::text NOT NULL,

  CONSTRAINT pkey_custom_data PRIMARY KEY(= custom_data_id),

) WITHOUT OIDS;

 

CREATE INDEX idx_custom_data_key ON public.custom_da= ta USING btree (key);

 

CREATE INDEX idx_custom_data_value ON public.custom_= data  USING btree (value);

 

CREATE TRIGGER on_custom_data_changed AFTER INSERT O= R UPDATE OR DELETE

ON public.custom_data FOR EACH ROW

EXECUTE PROCEDURE public.on_change_custom_data();

 

CREATE OR REPLACE FUNCTION p= ublic.on_change_custom_data () <= /span>
RETURNS trigger AS 
$body$ 
BEGIN 
   IF TG_OP =3D 'UPDATE' THEN<= span class=3D"apple-converted-space"> =

      RAISE N= OTICE 'Check custom data key start  : %', timeofday(); 
      IF NOT EXISTS (SELE= CT 1 FROM custom_data WHERE key =3D OLD.key ) THEN      

    &nbs= p; END IF; 
      RAISE NOTICE 'Check= custom data key end    : %', timeofday(); 
    END IF; 
    RETURN NULL; 
END; 
$body$ 
LANGUAGE 'plpgsql' 
VOLATILE CALLED ON NULL INPUT SECURITY I= NVOKER COST 100;

 

postgreSQL log:

HINWEIS:  Check custom = data key start  : Fri Oct 30 11:56:41.785000 2015 CET << start o= f IF NOT EXIST (...)

HINWEIS:  Check custom = data key end    : Fri Oct 30 11:56:47.145000 2015 CET << en= d of IF NOT EXISTS (...) : ~5.4 seconds

 
Query OK, 1 rows affected (5,367 sec)

 

Same query run in SQL editor= :

SELECT 1 FROM custom_data WH= ERE key=3D'key-1' =
1 rows returned (16 ms)

 

As you can see there=B4s a h= uge runtime difference between the select query used in the trigger functio= n and the one run from the SQL editor.

 

 

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_d9752446b5164156836d9bb97bacfe58EX2k13ocsnetlocal_--