Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1TvGBL-00055a-Cu for pgsql-performance@arkaria.postgresql.org; Tue, 15 Jan 2013 23:44:39 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.72) (envelope-from ) id 1TvGBK-00082D-9t for pgsql-performance@arkaria.postgresql.org; Tue, 15 Jan 2013 23:44:38 +0000 Received: from makus.postgresql.org ([98.129.198.125]) by malur.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1TvGBI-000827-NI for pgsql-performance@postgresql.org; Tue, 15 Jan 2013 23:44:37 +0000 Received: from mail-wg0-f50.google.com ([74.125.82.50]) by makus.postgresql.org with esmtp (Exim 4.72) (envelope-from ) id 1TvGBG-00017T-4d for pgsql-performance@postgresql.org; Tue, 15 Jan 2013 23:44:35 +0000 Received: by mail-wg0-f50.google.com with SMTP id es5so482575wgb.29 for ; Tue, 15 Jan 2013 15:44:32 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=x-received:content-type:mime-version:subject:from:in-reply-to:date :cc:message-id:references:to:x-mailer; bh=+HQPRuIgRNANEaiJjyodKxjIXZNPJl4mcLdQLLpkCSk=; b=x0H1aukH4X85ppIxhG/0i7GsOUARBEr7Zx+Sqc6tfFOoYtgDhVbkaGMEIvFWNqLLqG lMpf6n/edZm7peIupyVnAOxvDJSoxpL0ue2Ql1amtJZjajWDHDDNqk0QuzhjhYmlqeVa Ale1RetOnMhIwV78+qOfHocQc3fJPUCQRMLMz4r1RNAGh5xvA8cN3FaGSojOccPP93GH j5eaLQyHmRyrRKfRU02epyN6jXvsXikAytP1MVqL2tV3slyCboSYwARzQm/EM7ESN61A /A7TQfMTPTIIsYK5cGk3aMVN0MY+5HRf0yA0ldGGHG8wPrdkH2yx6neaaVDg16C8Sr+U Askw== X-Received: by 10.180.14.10 with SMTP id l10mr6525723wic.7.1358293472752; Tue, 15 Jan 2013 15:44:32 -0800 (PST) Received: from [192.168.1.40] (132.Red-83-53-228.dynamicIP.rima-tde.net. [83.53.228.132]) by mx.google.com with ESMTPS id hu8sm5598583wib.6.2013.01.15.15.44.30 (version=TLSv1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Tue, 15 Jan 2013 15:44:31 -0800 (PST) Content-Type: multipart/alternative; boundary="Apple-Mail=_144FF501-99FB-4795-BB27-202CE32DE786" Mime-Version: 1.0 (Mac OS X Mail 6.2 \(1499\)) Subject: Re: Insert performance for large transaction with multiple COPY FROM From: Horst Dehmer In-Reply-To: Date: Tue, 15 Jan 2013 23:44:29 +0000 Cc: "pgsql-performance@postgresql.org" Message-Id: References: <78A65A52-C49D-4CA4-9A63-1F5F120BC7E7@gmail.com> To: Jeff Janes X-Mailer: Apple Mail (2.1499) X-Pg-Spam-Score: -2.6 (--) 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 --Apple-Mail=_144FF501-99FB-4795-BB27-202CE32DE786 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=iso-8859-1 After more testing I have gained some insights: The foreign key constraints are NOT responsible for the low COPY FROM = performance in my case. I forgot about the indexes which are created = along with the FK constraints. Besides the primary key CONSTRAINT obj_item_loc_pkey PRIMARY KEY (obj_item_id, loc_id, = obj_item_loc_ix), the table OBJ_ITEM_LOC has four additional indexes (let's call them = idx_1 through idx_4) CREATE INDEX idx_1 ON obj_item_loc USING btree (rec_id); CREATE INDEX idx_2 ON obj_item_loc USING btree (loc_id); CREATE INDEX idx_3 ON obj_item_loc USING btree (rptd_id); CREATE INDEX idx_4 ON obj_item_loc USING btree (obj_item_id); The indexes 2 to 4 are intended to speed up joins between OBJ_ITEM_LOC = and LOC (loc_id), RPTD (rptd_id) and OBJ_ITEM (obj_item) respectively (and = I'm highly suspicious if this makes sense at all.) idx_4 together with a simple select in the tables on-insert trigger is = slowing things down considerably. With idx_4 and the trigger rates are 44100 rows, 0:00:04.576, 9637 r/s: LOC 2101 rows, 0:00:00.221, 9506 r/s: OBJ_ITEM 2101 rows, 0:00:00.278, 7557 r/s: ORG 94713 rows, 0:00:18.502, 5119 r/s: RPTD 44100 rows, 0:03:03.437, 240 r/s: OBJ_ITEM_LOC imported 187115 record in 0:03:27.081 =3D> 903 r/s pg_statio comes up with same big numbers (reads =3D bad, hits =3D not so = bad?): relname | heap_blks_read | heap_blks_hit | idx_blks_read | = idx_blks_hit=20 = --------------+----------------+---------------+---------------+----------= ---- obj_item_loc | 1262 | 9908013 | 1199 | = 1682005 rptd | 4434 | 279022 | 1806 | = 1270746 org | 38 | 191559 | 19 | = 201071 obj_item | 84 | 92476 | 29 | = 104134 loc | 768 | 88902 | 597 | = 352680 (5 rows) Dropping idx_1, idx_2 and idx_3 at the same time has no significant = impact. But take away idx_4 only: 44100 rows, 0:00:04.558, 9675 r/s: LOC 2101 rows, 0:00:00.220, 9593 r/s: OBJ_ITEM 2101 rows, 0:00:00.275, 7640 r/s: ORG 94713 rows, 0:00:18.407, 5145 r/s: RPTD 44100 rows, 0:00:11.433, 3857 r/s: OBJ_ITEM_LOC imported 187115 record in 0:00:34.938 =3D> 5355 r/s Hm, not bad. Now for the select statement in the on insert trigger: SELECT *=20 FROM obj_item_loc=20 WHERE obj_item_loc.obj_item_id =3D NEW.obj_item_id=20 AND obj_item_loc.loc_id =3D NEW.loc_id=20 AND obj_item_loc.obj_item_loc_ix =3D NEW.obj_item_loc_ix=20 INTO old; Executing this query AFTER the bulk insert (and probably some = auto-vacuuming) the query plan looks like this explain analyze=20 select *=20 from obj_item_loc=20 where (obj_item_id, loc_id, obj_item_loc_ix) =3D = (10903011224100014650,10903010224100089226,10900024100000140894) QUERY PLAN =20= -------------- Index Scan using obj_item_loc_loc_id_idx on obj_item_loc =20 (cost=3D0.00..8.36 rows=3D1 width=3D329)=20 (actual time=3D0.039..0.040 rows=3D1 loops=3D1) Index Cond: (loc_id =3D 10903010224100089226::numeric) Filter: ((obj_item_id =3D 10903011224100014650::numeric) AND=20 (obj_item_loc_ix =3D 10900024100000140894::numeric)) Total runtime: 0.079 ms After some head-scratching I realized that obj_item_id is just = referencing a meager 2101 rows which probably makes not for a good index = candidate. So, the query plan make some sense, I guess. Now I have some (more) questions: 1. How do I know which index (if any) is chosen for a select statement = inside a trigger during a bulk load transaction? (or for that matter: a = series of recursive plpgsql functions) 2. The query planner depends on stats collected by auto-vacuum/vacuum = analyze, right? Does stats collecting also happen during a lengthy = transaction?=20 3. Is it possible (or even advisable) to trigger vacuum analyze inside = an ongoing transaction. Let's say load 10,000 rows of table A, analyze = table A, insert the next 10,000 rows, analyze again, ... I'm sorry if this is basic stuff I'm asking here, but especially point 2 = is bothering me. -- Kind regards Horst Dehmer On 12.01.2013, at 01:17, Jeff Janes wrote: > On Friday, January 11, 2013, Horst Dehmer wrote: >=20 > Except - and that's the wall I'm hitting - for one table which yielded = just 75 records/second. > The main 'problem' seem to be the FK constraints. Dropping just them = restored insert performance for this table to 6k records/s. >=20 > It sure sounds like you don't have enough RAM to hold the foreign-key = table data needed to check the constraints, so every insert needs one = disk revolution to fetch the data. >=20 > If you drop the indexes and constraints one at a time until it speeds = up, is there a certain one that is the culprit?=20 >=20 > You can look in pg_statio_user_tables to see what tables and indexes = have high io being driven by the bulk loading. >=20 > Use "top" to see of the server is mostly IO bound or CPU bound. >=20 > Cheers, >=20 > Jeff --Apple-Mail=_144FF501-99FB-4795-BB27-202CE32DE786 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=iso-8859-1 After = more testing I have gained some insights:

The foreign key = constraints are NOT responsible for the low COPY FROM performance in my = case. I forgot about the indexes which are created along with the FK = constraints.

Besides the primary = key

CONSTRAINT obj_item_loc_pkey PRIMARY = KEY (obj_item_id, loc_id, = obj_item_loc_ix),

the = table OBJ_ITEM_LOC has four additional indexes (let's = call them idx_1 through idx_4)

CREATE = INDEX idx_1 ON obj_item_loc USING btree (rec_id);
CREATE INDEX = idx_2 ON obj_item_loc USING btree (loc_id);
CREATE INDEX idx_3 = ON obj_item_loc USING btree (rptd_id);
CREATE INDEX idx_4 ON = obj_item_loc USING btree = (obj_item_id);

The indexes 2 to 4 are = intended to speed up joins between OBJ_ITEM_LOC and
LOC = (loc_id), RPTD (rptd_id) and OBJ_ITEM (obj_item) respectively (and I'm = highly suspicious if this makes sense at = all.)

idx_4 together with a simple select in = the tables on-insert trigger is slowing things down = considerably.
With idx_4 and the trigger rates = are

 44100 rows, 0:00:04.576,   = 9637 r/s: LOC
  2101 rows, 0:00:00.221,   9506 r/s: = OBJ_ITEM
  2101 rows, 0:00:00.278,   7557 r/s: = ORG
 94713 rows, 0:00:18.502,   5119 r/s: = RPTD
 44100 rows, 0:03:03.437,    240 r/s: = OBJ_ITEM_LOC
imported 187115 record in 0:03:27.081 =3D> 903 = r/s

pg_statio comes up with same big numbers = (reads =3D bad, hits =3D not so bad?):

  =  relname    | heap_blks_read | heap_blks_hit | = idx_blks_read | = idx_blks_hit 
--------------+----------------+-------------= --+---------------+--------------
 obj_item_loc |   =         1262 |       9908013 |   =        1199 |     =  1682005
 rptd         |   =         4434 |        279022 | =          1806 |     =  1270746
 org          | =             38 |       =  191559 |            19 |   =     201071
 obj_item     |   =           84 |         = 92476 |            29 |     =   104134
 loc          | =            768 |       =   88902 |           597 |     =   352680
(5 rows)

Dropping = idx_1, idx_2 and idx_3 at the same time has no significant impact. But = take away idx_4 only:

 44100 rows, = 0:00:04.558,   9675 r/s: LOC
  2101 rows, = 0:00:00.220,   9593 r/s: OBJ_ITEM
  2101 rows, = 0:00:00.275,   7640 r/s: ORG
 94713 rows, = 0:00:18.407,   5145 r/s: RPTD
 44100 rows, = 0:00:11.433,   3857 r/s: OBJ_ITEM_LOC
imported 187115 = record in 0:00:34.938 =3D> 5355 = r/s

Hm, not bad. Now for the select = statement in the on insert trigger:

  =    = SELECT = * 
FROM = obj_item_loc 
WHERE = obj_item_loc.obj_item_id =3D = NEW.obj_item_id 
AND obj_item_loc.loc_id =3D = NEW.loc_id 
AND obj_item_loc.obj_item_loc_ix =3D = NEW.obj_item_loc_ix 
INTO = old;

Executing this query AFTER = the bulk insert (and probably some auto-vacuuming) the query plan looks = like this

explain = analyze 
select = * 
from = obj_item_loc 
where = (obj_item_id, loc_id, obj_item_loc_ix) =3D
= (10903011224100014650,10903010224100089226,10900024100000140894)

QUERY PLAN           =                     =                     =           =   
--------------
 Index Scan using = obj_item_loc_loc_id_idx on obj_item_loc  
= (cost=3D0.00..8.36 rows=3D1 width=3D329) 
(actual = time=3D0.039..0.040 rows=3D1 loops=3D1)
   Index = Cond: (loc_id =3D 10903010224100089226::numeric)
  =  Filter: ((obj_item_id =3D 10903011224100014650::numeric) = AND 
(obj_item_loc_ix =3D = 10900024100000140894::numeric))
 Total runtime: 0.079 = ms

After some head-scratching I realized = that obj_item_id is just referencing a meager 2101 rows which probably = makes not for a good index candidate. So, the query plan make some = sense, I guess.

Now I have some (more) = questions:

1. How do I know which index = (if any) is chosen for a select statement inside a trigger during a bulk = load transaction? (or for that matter: a series of recursive plpgsql = functions)
2. The query planner depends on stats collected by = auto-vacuum/vacuum analyze, right? Does stats collecting also happen = during a lengthy transaction? 
3. Is it possible (or even = advisable) to trigger vacuum analyze inside an ongoing transaction. = Let's say load 10,000 rows of table A, analyze table A, insert the next = 10,000 rows, analyze again, ...

I'm sorry if = this is basic stuff I'm asking here, but especially point 2 is bothering = me.

--
Kind regards
Horst = Dehmer

On 12.01.2013, at 01:17, Jeff Janes = <jeff.janes@gmail.com> = wrote:

On Friday, January 11, 2013, Horst Dehmer = wrote:

Except - and that's = the wall I'm hitting - for one table which yielded just 75 = records/second.
The main = 'problem' seem to be the FK constraints. Dropping just them restored = insert performance for this table to 6k records/s.

It sure sounds like you don't = have enough RAM to hold the foreign-key table data needed to check the = constraints, so every insert needs one disk revolution to fetch the = data.

If you drop the indexes and constraints one at a = time until it speeds up, is there a certain one that is the = culprit? 

You can look = in pg_statio_user_tables to see what tables and indexes have high = io being driven by the bulk loading.

Use "top" to see of the server is mostly IO bound or = CPU = bound.

Cheers,

Jeff

= --Apple-Mail=_144FF501-99FB-4795-BB27-202CE32DE786--