Subject: Re: same plan, add 1 condition, 1900x slower
From: Mitch Skinner <mitch@egcrc.net>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: pgsql-performance@postgresql.org
In-Reply-To: <10164.1131643400@sss.pgh.pa.us>
References: <1131630176.29496.91.camel@enzian>
 <10164.1131643400@sss.pgh.pa.us>
Content-Type: multipart/mixed; boundary="=-hgMMVV2ifun8oB6Cmlku"
Date: Fri, 11 Nov 2005 01:17:15 -0800
Message-Id: <1131700635.29496.136.camel@enzian>
Mime-Version: 1.0


--=-hgMMVV2ifun8oB6Cmlku
Content-Type: text/plain
Content-Transfer-Encoding: 7bit

On Thu, 2005-11-10 at 12:23 -0500, Tom Lane wrote:
> Apparently, you are using a platform and/or locale in which strcoll() is
> spectacularly, god-awfully slow --- on the order of 10 msec per comparison.

The version with the condition is definitely doing more I/O.  The
version without the condition doesn't read at all.  I strace'd an
explain analyze for each separately, and this is what I ended up with
(the first is with the condition, the second is without):

bash-2.05b$ cut '-d(' -f1 subsourcestrace | sort | uniq -c
   7127 gettimeofday
  75213 _llseek
      1 Process 30227 attached - interrupt to quit
      1 Process 30227 detached
 148671 read
      2 recv
      4 semop
      4 send
bash-2.05b$ cut '-d(' -f1 subsourcestrace-nocond | sort | uniq -c
   9103 gettimeofday
      7 _llseek
      1 Process 30227 attached - interrupt to quit
      1 Process 30227 detached
      2 recv
      4 send

For the moment, all of the rows in the view I'm selecting from satisfy
the condition, so the output of both queries is the same.  The relevant
rows of the underlying tables are probably pretty contiguous (all of the
rows satisfying the condition and the join were inserted at the same
time).  Could it just be the result of a weird physical distribution of
data in the table/index files?  For the fast query, the actual number of
rows is a lot less than the planner expects.

> This is a bit hard to believe but I can't make sense of those numbers
> any other way.  What is the platform exactly, and what database locale
> and encoding are you using?

It's RHEL 3 on x86:
[root@rehoboam root]# uname -a
Linux rehoboam 2.4.21-32.0.1.ELsmp #1 SMP Tue May 17 17:52:23 EDT 2005
i686 i686 i386 GNU/Linux

The glibc version is 2.3.2.

statgen=# select current_setting('lc_collate');
 current_setting
-----------------
 en_US.UTF-8

Not sure what's relevant, but here's some more info:
The machine has 4.5GiB of RAM and a 5-disk Raid 5.  It's a dual xeon
3.2ghz.

           relname           | relpages |  reltuples
-----------------------------+----------+-------------
 external_id_map             |   126883 | 1.55625e+07
 external_id_map_primary_key |    64607 | 1.55625e+07
 subject                     |       31 |        1186
 subject_pkey                |       19 |        1186

I've attached the output of "select name, setting from pg_settings".

And, in case my original message isn't handy, the explain analyze output
and table/view info is below.

Thanks for taking a look,
Mitch

statgen=> explain analyze select * from subject_source;

QUERY PLAN 
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Merge Join  (cost=0.00..330.72 rows=1186 width=46) (actual
time=0.051..8.890 rows=1186 loops=1)
   Merge Cond: ("outer".id = "inner".target_id)
   ->  Index Scan using subject_pkey on subject norm  (cost=0.00..63.36
rows=1186 width=28) (actual time=0.022..1.441 rows=1186 loops=1)
   ->  Index Scan using external_id_map_primary_key on external_id_map
eim  (cost=0.00..2485226.70 rows=15562513 width=26) (actual
time=0.016..2.532 rows=2175 loops=1)
 Total runtime: 9.592 ms
(5 rows)

statgen=> explain analyze select * from subject_source where
source='SCH';

QUERY PLAN 
------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Merge Join  (cost=0.00..1147.33 rows=1 width=46) (actual
time=0.054..20258.161 rows=1186 loops=1)
   Merge Cond: ("outer".id = "inner".target_id)
   ->  Index Scan using subject_pkey on subject norm  (cost=0.00..63.36
rows=1186 width=28) (actual time=0.022..1.478 rows=1186 loops=1)
   ->  Index Scan using external_id_map_primary_key on external_id_map
eim  (cost=0.00..2524132.99 rows=2335 width=26) (actual
time=0.022..20252.326 rows=1186 loops=1)
         Filter: (source = 'SCH'::bpchar)
 Total runtime: 20258.922 ms
(6 rows)

statgen=> \d subject_source
         View "public.subject_source"
  Column   |         Type          | Modifiers
-----------+-----------------------+-----------
 id        | bigint                |
 sex       | integer               |
 parent1   | bigint                |
 parent2   | bigint                |
 source    | character(3)          |
 source_id | character varying(32) |
View definition:
 SELECT norm.id, norm.sex, norm.parent1, norm.parent2, eim.source,
eim.source_id
   FROM subject norm
   JOIN util.external_id_map eim ON norm.id = eim.target_id;

statgen=> \d subject
    Table "public.subject"
 Column  |  Type   | Modifiers
---------+---------+-----------
 id      | bigint  | not null
 sex     | integer |
 parent1 | bigint  |
 parent2 | bigint  |
Indexes:
    "subject_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
    "subject_parent1" FOREIGN KEY (parent1) REFERENCES subject(id)
DEFERRABLE INITIALLY DEFERRED
    "subject_parent2" FOREIGN KEY (parent2) REFERENCES subject(id)
DEFERRABLE INITIALLY DEFERRED
    "subject_id_map" FOREIGN KEY (id) REFERENCES
util.external_id_map(target_id) DEFERRABLE INITIALLY DEFERRED

statgen=> \d util.external_id_map
         Table "util.external_id_map"
  Column   |         Type          | Modifiers
-----------+-----------------------+-----------
 source_id | character varying(32) | not null
 source    | character(3)          | not null
 target_id | bigint                | not null
Indexes:
    "external_id_map_primary_key" PRIMARY KEY, btree (target_id)
    "external_id_map_source_source_id_unique" UNIQUE, btree (source,
source_id)
    "external_id_map_source" btree (source)
    "external_id_map_source_target_id" btree (source, target_id)
Foreign-key constraints:
    "external_id_map_source" FOREIGN KEY (source) REFERENCES
util.source(id)


--=-hgMMVV2ifun8oB6Cmlku
Content-Disposition: attachment; filename=pg_settings
Content-Type: text/plain; name=pg_settings; charset=utf-8
Content-Transfer-Encoding: base64

ICAgICAgICAgICAgICBuYW1lICAgICAgICAgICAgICB8ICAgIHNldHRpbmcgICAgIA0KLS0tLS0t
LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0rLS0tLS0tLS0tLS0tLS0tLQ0KIGFkZF9taXNzaW5n
X2Zyb20gICAgICAgICAgICAgICB8IG9uDQogYXJjaGl2ZV9jb21tYW5kICAgICAgICAgICAgICAg
IHwgdW5zZXQNCiBhdXN0cmFsaWFuX3RpbWV6b25lcyAgICAgICAgICAgfCBvZmYNCiBhdXRoZW50
aWNhdGlvbl90aW1lb3V0ICAgICAgICAgfCA2MA0KIGJnd3JpdGVyX2RlbGF5ICAgICAgICAgICAg
ICAgICB8IDIwMA0KIGJnd3JpdGVyX21heHBhZ2VzICAgICAgICAgICAgICB8IDEwMA0KIGJnd3Jp
dGVyX3BlcmNlbnQgICAgICAgICAgICAgICB8IDENCiBibG9ja19zaXplICAgICAgICAgICAgICAg
ICAgICAgfCA4MTkyDQogY2hlY2tfZnVuY3Rpb25fYm9kaWVzICAgICAgICAgIHwgb24NCiBjaGVj
a3BvaW50X3NlZ21lbnRzICAgICAgICAgICAgfCAzMg0KIGNoZWNrcG9pbnRfdGltZW91dCAgICAg
ICAgICAgICB8IDMwMA0KIGNoZWNrcG9pbnRfd2FybmluZyAgICAgICAgICAgICB8IDYwDQogY2xp
ZW50X2VuY29kaW5nICAgICAgICAgICAgICAgIHwgU1FMX0FTQ0lJDQogY2xpZW50X21pbl9tZXNz
YWdlcyAgICAgICAgICAgIHwgbm90aWNlDQogY29tbWl0X2RlbGF5ICAgICAgICAgICAgICAgICAg
IHwgMA0KIGNvbW1pdF9zaWJsaW5ncyAgICAgICAgICAgICAgICB8IDUNCiBjcHVfaW5kZXhfdHVw
bGVfY29zdCAgICAgICAgICAgfCAwLjAwMQ0KIGNwdV9vcGVyYXRvcl9jb3N0ICAgICAgICAgICAg
ICB8IDAuMDAyNQ0KIGNwdV90dXBsZV9jb3N0ICAgICAgICAgICAgICAgICB8IDAuMDENCiBjdXN0
b21fdmFyaWFibGVfY2xhc3NlcyAgICAgICAgfCB1bnNldA0KIERhdGVTdHlsZSAgICAgICAgICAg
ICAgICAgICAgICB8IElTTywgTURZDQogZGJfdXNlcl9uYW1lc3BhY2UgICAgICAgICAgICAgIHwg
b2ZmDQogZGVhZGxvY2tfdGltZW91dCAgICAgICAgICAgICAgIHwgMTAwMA0KIGRlYnVnX3ByZXR0
eV9wcmludCAgICAgICAgICAgICB8IG9mZg0KIGRlYnVnX3ByaW50X3BhcnNlICAgICAgICAgICAg
ICB8IG9mZg0KIGRlYnVnX3ByaW50X3BsYW4gICAgICAgICAgICAgICB8IG9mZg0KIGRlYnVnX3By
aW50X3Jld3JpdHRlbiAgICAgICAgICB8IG9mZg0KIGRlYnVnX3NoYXJlZF9idWZmZXJzICAgICAg
ICAgICB8IDANCiBkZWZhdWx0X3N0YXRpc3RpY3NfdGFyZ2V0ICAgICAgfCAxMA0KIGRlZmF1bHRf
dGFibGVzcGFjZSAgICAgICAgICAgICB8IHVuc2V0DQogZGVmYXVsdF90cmFuc2FjdGlvbl9pc29s
YXRpb24gIHwgcmVhZCBjb21taXR0ZWQNCiBkZWZhdWx0X3RyYW5zYWN0aW9uX3JlYWRfb25seSAg
fCBvZmYNCiBkZWZhdWx0X3dpdGhfb2lkcyAgICAgICAgICAgICAgfCBvZmYNCiBlZmZlY3RpdmVf
Y2FjaGVfc2l6ZSAgICAgICAgICAgfCA2NTUzNg0KIGVuYWJsZV9oYXNoYWdnICAgICAgICAgICAg
ICAgICB8IG9uDQogZW5hYmxlX2hhc2hqb2luICAgICAgICAgICAgICAgIHwgb24NCiBlbmFibGVf
aW5kZXhzY2FuICAgICAgICAgICAgICAgfCBvbg0KIGVuYWJsZV9tZXJnZWpvaW4gICAgICAgICAg
ICAgICB8IG9uDQogZW5hYmxlX25lc3Rsb29wICAgICAgICAgICAgICAgIHwgb24NCiBlbmFibGVf
c2Vxc2NhbiAgICAgICAgICAgICAgICAgfCBvbg0KIGVuYWJsZV9zb3J0ICAgICAgICAgICAgICAg
ICAgICB8IG9uDQogZW5hYmxlX3RpZHNjYW4gICAgICAgICAgICAgICAgIHwgb24NCiBleHBsYWlu
X3ByZXR0eV9wcmludCAgICAgICAgICAgfCBvbg0KIGV4dHJhX2Zsb2F0X2RpZ2l0cyAgICAgICAg
ICAgICB8IDANCiBmcm9tX2NvbGxhcHNlX2xpbWl0ICAgICAgICAgICAgfCA4DQogZnN5bmMgICAg
ICAgICAgICAgICAgICAgICAgICAgIHwgb24NCiBnZXFvICAgICAgICAgICAgICAgICAgICAgICAg
ICAgfCBvbg0KIGdlcW9fZWZmb3J0ICAgICAgICAgICAgICAgICAgICB8IDUNCiBnZXFvX2dlbmVy
YXRpb25zICAgICAgICAgICAgICAgfCAwDQogZ2Vxb19wb29sX3NpemUgICAgICAgICAgICAgICAg
IHwgMA0KIGdlcW9fc2VsZWN0aW9uX2JpYXMgICAgICAgICAgICB8IDINCiBnZXFvX3RocmVzaG9s
ZCAgICAgICAgICAgICAgICAgfCAxMg0KIGludGVnZXJfZGF0ZXRpbWVzICAgICAgICAgICAgICB8
IG9mZg0KIGpvaW5fY29sbGFwc2VfbGltaXQgICAgICAgICAgICB8IDgNCiBsY19jb2xsYXRlICAg
ICAgICAgICAgICAgICAgICAgfCBlbl9VUy5VVEYtOA0KIGxjX2N0eXBlICAgICAgICAgICAgICAg
ICAgICAgICB8IGVuX1VTLlVURi04DQogbGNfbWVzc2FnZXMgICAgICAgICAgICAgICAgICAgIHwg
ZW5fVVMuVVRGLTgNCiBsY19tb25ldGFyeSAgICAgICAgICAgICAgICAgICAgfCBlbl9VUy5VVEYt
OA0KIGxjX251bWVyaWMgICAgICAgICAgICAgICAgICAgICB8IGVuX1VTLlVURi04DQogbGNfdGlt
ZSAgICAgICAgICAgICAgICAgICAgICAgIHwgZW5fVVMuVVRGLTgNCiBsaXN0ZW5fYWRkcmVzc2Vz
ICAgICAgICAgICAgICAgfCAqDQogbG9nX2Nvbm5lY3Rpb25zICAgICAgICAgICAgICAgIHwgb2Zm
DQogbG9nX2Rlc3RpbmF0aW9uICAgICAgICAgICAgICAgIHwgc3RkZXJyDQogbG9nX2Rpc2Nvbm5l
Y3Rpb25zICAgICAgICAgICAgIHwgb2ZmDQogbG9nX2R1cmF0aW9uICAgICAgICAgICAgICAgICAg
IHwgb2ZmDQogbG9nX2Vycm9yX3ZlcmJvc2l0eSAgICAgICAgICAgIHwgZGVmYXVsdA0KIGxvZ19l
eGVjdXRvcl9zdGF0cyAgICAgICAgICAgICB8IG9mZg0KIGxvZ19ob3N0bmFtZSAgICAgICAgICAg
ICAgICAgICB8IG9mZg0KIGxvZ19saW5lX3ByZWZpeCAgICAgICAgICAgICAgICB8IHVuc2V0DQog
bG9nX21pbl9kdXJhdGlvbl9zdGF0ZW1lbnQgICAgIHwgLTENCiBsb2dfbWluX2Vycm9yX3N0YXRl
bWVudCAgICAgICAgfCBwYW5pYw0KIGxvZ19taW5fbWVzc2FnZXMgICAgICAgICAgICAgICB8IG5v
dGljZQ0KIGxvZ19wYXJzZXJfc3RhdHMgICAgICAgICAgICAgICB8IG9mZg0KIGxvZ19wbGFubmVy
X3N0YXRzICAgICAgICAgICAgICB8IG9mZg0KIGxvZ19yb3RhdGlvbl9hZ2UgICAgICAgICAgICAg
ICB8IDE0NDANCiBsb2dfcm90YXRpb25fc2l6ZSAgICAgICAgICAgICAgfCAwDQogbG9nX3N0YXRl
bWVudCAgICAgICAgICAgICAgICAgIHwgbm9uZQ0KIGxvZ19zdGF0ZW1lbnRfc3RhdHMgICAgICAg
ICAgICB8IG9mZg0KIGxvZ190cnVuY2F0ZV9vbl9yb3RhdGlvbiAgICAgICB8IG9uDQogbWFpbnRl
bmFuY2Vfd29ya19tZW0gICAgICAgICAgIHwgNjU1MzYNCiBtYXhfY29ubmVjdGlvbnMgICAgICAg
ICAgICAgICAgfCAxMDANCiBtYXhfZmlsZXNfcGVyX3Byb2Nlc3MgICAgICAgICAgfCAxMDAwDQog
bWF4X2ZzbV9wYWdlcyAgICAgICAgICAgICAgICAgIHwgMjAwMDANCiBtYXhfZnNtX3JlbGF0aW9u
cyAgICAgICAgICAgICAgfCAxMDAwDQogbWF4X2Z1bmN0aW9uX2FyZ3MgICAgICAgICAgICAgIHwg
MzINCiBtYXhfaWRlbnRpZmllcl9sZW5ndGggICAgICAgICAgfCA2Mw0KIG1heF9pbmRleF9rZXlz
ICAgICAgICAgICAgICAgICB8IDMyDQogbWF4X2xvY2tzX3Blcl90cmFuc2FjdGlvbiAgICAgIHwg
NjQNCiBtYXhfc3RhY2tfZGVwdGggICAgICAgICAgICAgICAgfCAyMDQ4DQogcGFzc3dvcmRfZW5j
cnlwdGlvbiAgICAgICAgICAgIHwgb24NCiBwb3J0ICAgICAgICAgICAgICAgICAgICAgICAgICAg
fCA1NDMyDQogcHJlX2F1dGhfZGVsYXkgICAgICAgICAgICAgICAgIHwgMA0KIHJhbmRvbV9wYWdl
X2Nvc3QgICAgICAgICAgICAgICB8IDQNCiByZWRpcmVjdF9zdGRlcnIgICAgICAgICAgICAgICAg
fCBvbg0KIHJlZ2V4X2ZsYXZvciAgICAgICAgICAgICAgICAgICB8IGFkdmFuY2VkDQogcmVuZGV6
dm91c19uYW1lICAgICAgICAgICAgICAgIHwgdW5zZXQNCiBzZWFyY2hfcGF0aCAgICAgICAgICAg
ICAgICAgICAgfCAkdXNlcixwdWJsaWMNCiBzZXJ2ZXJfZW5jb2RpbmcgICAgICAgICAgICAgICAg
fCBTUUxfQVNDSUkNCiBzZXJ2ZXJfdmVyc2lvbiAgICAgICAgICAgICAgICAgfCA4LjAuMw0KIHNo
YXJlZF9idWZmZXJzICAgICAgICAgICAgICAgICB8IDMyNzY4DQogc2lsZW50X21vZGUgICAgICAg
ICAgICAgICAgICAgIHwgb2ZmDQogc3FsX2luaGVyaXRhbmNlICAgICAgICAgICAgICAgIHwgb24N
CiBzc2wgICAgICAgICAgICAgICAgICAgICAgICAgICAgfCBvZmYNCiBzdGF0ZW1lbnRfdGltZW91
dCAgICAgICAgICAgICAgfCAwDQogc3RhdHNfYmxvY2tfbGV2ZWwgICAgICAgICAgICAgIHwgb2Zm
DQogc3RhdHNfY29tbWFuZF9zdHJpbmcgICAgICAgICAgIHwgb24NCiBzdGF0c19yZXNldF9vbl9z
ZXJ2ZXJfc3RhcnQgICAgfCBvbg0KIHN0YXRzX3Jvd19sZXZlbCAgICAgICAgICAgICAgICB8IG9m
Zg0KIHN0YXRzX3N0YXJ0X2NvbGxlY3RvciAgICAgICAgICB8IG9uDQogc3VwZXJ1c2VyX3Jlc2Vy
dmVkX2Nvbm5lY3Rpb25zIHwgMg0KIHN5c2xvZ19mYWNpbGl0eSAgICAgICAgICAgICAgICB8IExP
Q0FMMA0KIHN5c2xvZ19pZGVudCAgICAgICAgICAgICAgICAgICB8IHBvc3RncmVzDQogVGltZVpv
bmUgICAgICAgICAgICAgICAgICAgICAgIHwgUFNUOFBEVA0KIHRyYWNlX25vdGlmeSAgICAgICAg
ICAgICAgICAgICB8IG9mZg0KIHRyYW5zYWN0aW9uX2lzb2xhdGlvbiAgICAgICAgICB8IHJlYWQg
Y29tbWl0dGVkDQogdHJhbnNhY3Rpb25fcmVhZF9vbmx5ICAgICAgICAgIHwgb2ZmDQogdHJhbnNm
b3JtX251bGxfZXF1YWxzICAgICAgICAgIHwgb2ZmDQogdW5peF9zb2NrZXRfZ3JvdXAgICAgICAg
ICAgICAgIHwgdW5zZXQNCiB1bml4X3NvY2tldF9wZXJtaXNzaW9ucyAgICAgICAgfCA1MTENCiB2
YWN1dW1fY29zdF9kZWxheSAgICAgICAgICAgICAgfCAwDQogdmFjdXVtX2Nvc3RfbGltaXQgICAg
ICAgICAgICAgIHwgMjAwDQogdmFjdXVtX2Nvc3RfcGFnZV9kaXJ0eSAgICAgICAgIHwgMjANCiB2
YWN1dW1fY29zdF9wYWdlX2hpdCAgICAgICAgICAgfCAxDQogdmFjdXVtX2Nvc3RfcGFnZV9taXNz
ICAgICAgICAgIHwgMTANCiB3YWxfYnVmZmVycyAgICAgICAgICAgICAgICAgICAgfCA4DQogd2Fs
X3N5bmNfbWV0aG9kICAgICAgICAgICAgICAgIHwgZmRhdGFzeW5jDQogd29ya19tZW0gICAgICAg
ICAgICAgICAgICAgICAgIHwgNjU1MzYNCiB6ZXJvX2RhbWFnZWRfcGFnZXMgICAgICAgICAgICAg
fCBvZmYNCigxMjggcm93cykNCg0K


--=-hgMMVV2ifun8oB6Cmlku--