Query plan changing when queried data does not

From: "Harry Hehl" <Harry(dot)Hehl(at)diskstream(dot)com>
To: <pgsql-performance(at)postgresql(dot)org>
Subject: Query plan changing when queried data does not
Date: 2006-12-18 16:32:19
Message-ID: 6AD4F3A63B017C4FB074E2C895AD1854E31A60@EXCHSRV.waterloonetworking.net
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

I have a database that has 3 tables with a relatively small number of
records in each. (see schema/counts below). These 3 tables are loaded
when the db is created and there are never any updates or deletes on the
3 tables. This database does have many other tables.

ds_tables 132 rows, ds_types 281 rows, ds_columns 2191 rows

When I run the query below on a new database where all the other tables
are empty except for the 3 tables that contain static information, the
query time is ~200ms. When I run the same query on a production database
that has many records in the other tables (3 static tables the same),
the query took ~7 seconds. When I run it again on a test database with
more data then the production database, but with a different
distribution of data, ~1.2 seconds.

I have seen this query take as much as 25 seconds because all seq scans
where used. Vacuum full analyze and reindex on ONLY the 3 static tables
reduced the query time.

All queries where run on the same computer with the same
postgresql.conf. i.e no configuration changes.

I am trying to find out what causes the query on production database to
be so much slower. The query is changing (index vs sequencial scan) when
the data remains the same.

Why would the existence of data in other tables affect the query
performance on the 3 static tables?

Why does vacuum full and reindex make a difference if the 3 tables are
never updated or records deleted?

Using postgresql 8.1.3.

<<QUERY>>
explain analyze select ds_tables.name as table_name, ds_columns.name as
column_name from ds_tables left join ds_columns on ds_tables.classid =
ds_columns.classid left join ds_types on ds_columns.typeid =
ds_types.typeid where ds_types.name like 'OMWeakObjRef<%>' and
lower(ds_columns.name) not in
('owner','ownergroup','generatedby','originator','extendedby','audituser
','settingclassdef','itemowner','srcobj','dstobj','srcweakobj','dstweako
bj','notificationcreateuser','metadataowner','rpcdef','settingdef','sett
ingparent','taskacceptuser','workobj','testref') and
lower(ds_tables.name) not in
('ds_omdatatest','ds_ommessage','ds_omusersetting','ds_omloginsession','
ds_omclassdef','ds_omuser','ds_omusergroupsetting','ds_omtestobject','ds
_omhomedirectory')and lower(ds_tables.name) like 'ds_om%';

<<<RESULT USING NEW DATABASE>>
Nested Loop (cost=34.48..73.15 rows=1 width=64) (actual
time=0.897..42.562 rows=55 loops=1)
-> Nested Loop (cost=34.48..61.38 rows=2 width=48) (actual
time=0.782..41.378 rows=61 loops=1)
-> Bitmap Heap Scan on ds_types (cost=2.02..9.63 rows=1
width=16) (actual time=0.160..0.707 rows=130 loops=1)
Filter: (name ~~ 'OMWeakObjRef<%>'::text)
-> Bitmap Index Scan on ds_types_name_key
(cost=0.00..2.02 rows=4 width=0) (actual time=0.124..0.124 rows=130
loops=1)
Index Cond: ((name >= 'OMWeakObjRef<'::text) AND
(name < 'OMWeakObjRef='::text))
-> Bitmap Heap Scan on ds_columns (cost=32.46..51.64 rows=9
width=64) (actual time=0.301..0.307 rows=0 loops=130)
Recheck Cond: (ds_columns.typeid = "outer".typeid)
Filter: ((lower(name) <> 'owner'::text) AND (lower(name)
<> 'ownergroup'::text) AND (lower(name) <> 'generatedby'::text) AND
(lower(name) <> 'originator'::text) AND (lower(name) <>
'extendedby'::text) AND (lower(name) <> 'audituser'::text) AND
(lower(name) <> 'settingclassdef'::text) AND (lower(name) <>
'itemowner'::text) AND (lower(name) <> 'srcobj'::text) AND (lower(name)
<> 'dstobj'::text) AND (lower(name) <> 'srcweakobj'::text) AND
(lower(name) <> 'dstweakobj'::text) AND (lower(name) <>
'notificationcreateuser'::text) AND (lower(name) <>
'metadataowner'::text) AND (lower(name) <> 'rpcdef'::text) AND
(lower(name) <> 'settingdef'::text) AND (lower(name) <>
'settingparent'::text) AND (lower(name) <> 'taskacceptuser'::text) AND
(lower(name) <> 'workobj'::text) AND (lower(name) <> 'testref'::text))
-> Bitmap Index Scan on ds_columns_pkey
(cost=0.00..32.46 rows=9 width=0) (actual time=0.293..0.293 rows=3
loops=130)
Index Cond: (ds_columns.typeid = "outer".typeid)
-> Index Scan using ds_tables_pkey on ds_tables (cost=0.00..5.87
rows=1 width=48) (actual time=0.012..0.014 rows=1 loops=61)
Index Cond: (ds_tables.classid = "outer".classid)
Filter: ((lower(name) <> 'ds_omdatatest'::text) AND
(lower(name) <> 'ds_ommessage'::text) AND (lower(name) <>
'ds_omusersetting'::text) AND (lower(name) <> 'ds_omloginsession'::text)
AND (lower(name) <> 'ds_omclassdef'::text) AND (lower(name) <>
'ds_omuser'::text) AND (lower(name) <> 'ds_omusergroupsetting'::text)
AND (lower(name) <> 'ds_omtestobject'::text) AND (lower(name) <>
'ds_omhomedirectory'::text) AND (lower(name) ~~ 'ds_om%'::text))
Total runtime: 191.034 ms
(15 rows)

<<<RESULT USING PRODUCTION DATABASE>>
Nested Loop (cost=27.67..69.70 rows=1 width=46) (actual
time=12.433..6905.152 rows=55 loops=1)
Join Filter: ("inner".typeid = "outer".typeid)
-> Index Scan using ds_types_name_key on ds_types (cost=0.00..5.57
rows=1 width=16) (actual time=0.062..1.209 rows=130 loops=1)
Index Cond: ((name >= 'OMWeakObjRef<'::text) AND (name <
'OMWeakObjRef='::text))
Filter: (name ~~ 'OMWeakObjRef<%>'::text)
-> Nested Loop (cost=27.67..63.94 rows=15 width=62) (actual
time=0.313..51.255 rows=1431 loops=130)
-> Seq Scan on ds_tables (cost=0.00..9.92 rows=1 width=48)
(actual time=0.007..0.718 rows=121 loops=130)
Filter: ((lower(name) <> 'ds_omdatatest'::text) AND
(lower(name) <> 'ds_ommessage'::text) AND (lower(name) <>
'ds_omusersetting'::text) AND(lower(name) <> 'ds_omloginsession'::text)
AND (lower(name) <> 'ds_omclassdef'::text) AND (lower(name) <>
'ds_omuser'::text) AND (lower(name) <> 'ds_omusergroupsetting'::text)
AND (lower(name) <> 'ds_omtestobject'::text) AND (lower(name) <>
'ds_omhomedirectory'::text) AND (lower(name) ~~ 'ds_om%'::text))
-> Bitmap Heap Scan on ds_columns (cost=27.67..53.81 rows=17
width=46) (actual time=0.305..0.384 rows=12 loops=15730)
Recheck Cond: ("outer".classid = ds_columns.classid)
Filter: ((lower(name) <> 'owner'::text) AND (lower(name)
<> 'ownergroup'::text) AND (lower(name) <> 'generatedby'::text) AND
(lower(name) <> 'originator'::text) AND (lower(name) <>
'extendedby'::text) AND (lower(name) <> 'audituser'::text) AND
(lower(name) <> 'settingclassdef'::text) AND (lower(name) <>
'itemowner'::text) AND (lower(name) <> 'srcobj'::text) AND (lower(name)
<> 'dstobj'::text) AND (lower(name) <> 'srcweakobj'::text) AND
(lower(name) <> 'dstweakobj'::text) AND (lower(name) <>
'notificationcreateuser'::text) AND (lower(name) <>
'metadataowner'::text) AND (lower(name) <> 'rpcdef'::text) AND
(lower(name) <> 'settingdef'::text) AND (lower(name) <>
'settingparent'::text) AND (lower(name) <> 'taskacceptuser'::text) AND
(lower(name) <> 'workobj'::text) AND (lower(name) <> 'testref'::text))
-> Bitmap Index Scan on ds_columns_pkey
(cost=0.00..27.67 rows=17 width=0) (actual time=0.291..0.291 rows=16
loops=15730)
Index Cond: ("outer".classid = ds_columns.classid)
Total runtime: 7064.142 ms
(14 rows)

Note: In the explain analyze result there is small difference in result
between the new db and production db because the new db initially has a
bit more info due to changes made after the production db was created).

<<<RESULT USING TEST DATABASE>>
(1 row) Nested Loop (cost=119.82..127.32 rows=1 width=46) (actual
time=76.067..574.193 rows=55 loops=1)
Join Filter: ("inner".typeid = "outer".typeid)
-> Index Scan using ds_types_name_key on ds_types (cost=0.00..6.51
rows=22 width=16) (actual time=25.948..26.763 rows=130 loops=1)
Index Cond: ((name >= 'OMWeakObjRef<'::text) AND (name <
'OMWeakObjRef='::text))
Filter: (name ~~ 'OMWeakObjRef<%>'::text)
-> Materialize (cost=119.82..119.84 rows=2 width=62) (actual
time=0.288..2.411 rows=1431 loops=130)
-> Nested Loop (cost=33.67..119.82 rows=2 width=62) (actual
time=37.288..94.879 rows=1431 loops=1)
-> Seq Scan on ds_tables (cost=0.00..59.80 rows=1
width=48) (actual time=15.208..15.968 rows=121 loops=1)
Filter: ((lower(name) <> 'ds_omdatatest'::text) AND
(lower(name) <> 'ds_ommessage'::text) AND (lower(name) <>
'ds_omusersetting'::text) AND (lower(name) <> 'ds_omloginsession'::text)
AND (lower(name) <> 'ds_omclassdef'::text) AND (lower(name) <>
'ds_omuser'::text) AND (lower(name) <> 'ds_omusergroupsetting'::text)
AND (lower(name) <> 'ds_omtestobject'::text) AND (lower(name) <>
'ds_omhomedirectory'::text) AND (lower(name) ~~ 'ds_om%'::text))
-> Bitmap Heap Scan on ds_columns (cost=33.67..59.81
rows=17 width=46) (actual time=0.502..0.617 rows=12 loops=121)
Recheck Cond: ("outer".classid =
ds_columns.classid)
Filter: ((lower(name) <> 'owner'::text) AND
(lower(name) <> 'ownergroup'::text) AND (lower(name) <>
'generatedby'::text) AND (lower(name) <> 'originator'::text) AND
(lower(name) <> 'extendedby'::text) AND (lower(name) <>
'audituser'::text) AND (lower(name) <> 'settingclassdef'::text)
AND(lower(name) <> 'itemowner'::text) AND (lower(name) <>
'srcobj'::text) AND (lower(name) <> 'dstobj'::text) AND (lower(name) <>
'srcweakobj'::text) AND (lower(name) <> 'dstweakobj'::text) AND
(lower(name) <> 'notificationcreateuser'::text) AND (lower(name) <>
'metadataowner'::text) AND (lower(name) <> 'rpcdef'::text) AND
(lower(name) <> 'settingdef'::text) AND (lower(name) <>
'settingparent'::text) AND (lower(name) <> 'taskacceptuser'::text) AND
(lower(name) <>'workobj'::text) AND (lower(name) <> 'testref'::text))
-> Bitmap Index Scan on ds_columns_pkey
(cost=0.00..33.67 rows=17 width=0) (actual time=0.313..0.313 rows=16
loops=121)
Index Cond: ("outer".classid =
ds_columns.classid)
Total runtime: 1216.834 ms

<<SCHEMA>>
Table "public.ds_tables"
Column | Type | Modifiers
---------------+---------+-----------
classid | ds_uuid | not null
name | text | not null
parentclassid | ds_uuid |
Indexes:
"ds_tables_pkey" PRIMARY KEY, btree (classid)
"ds_tables_name_key" UNIQUE, btree (name)
Foreign-key constraints:
"ds_tables_parentclassid_fkey" FOREIGN KEY (parentclassid)
REFERENCES ds_tables(classid)

Table "public.ds_types"
Column | Type | Modifiers
-----------------+---------+-----------
name | text | not null
typeid | ds_uuid | not null
internalsqltype | text | not null
Indexes:
"ds_types_pkey" PRIMARY KEY, btree (typeid)
"ds_types_name_key" UNIQUE, btree (name)

Table "public.ds_columns"
Column | Type | Modifiers
------------+---------+-----------
propertyid | ds_uuid | not null
classid | ds_uuid | not null
name | text | not null
typeid | ds_uuid | not null
Indexes:
"ds_columns_pkey" PRIMARY KEY, btree (propertyid, classid, typeid)
Foreign-key constraints:
"ds_columns_classid_fkey" FOREIGN KEY (classid) REFERENCES
ds_tables(classid)
"ds_columns_typeid_fkey" FOREIGN KEY (typeid) REFERENCES
ds_types(typeid)

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Tom Lane 2006-12-18 17:07:58 Re: Query plan changing when queried data does not
Previous Message Tom Lane 2006-12-18 15:51:01 Re: transaction ID wrap limit