Query plan changing when queried data does not - Mailing list pgsql-performance

From Harry Hehl
Subject Query plan changing when queried data does not
Date
Msg-id 6AD4F3A63B017C4FB074E2C895AD1854E31A60@EXCHSRV.waterloonetworking.net
Whole thread Raw
Responses Re: Query plan changing when queried data does not
List 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','dstweakobj','notificationcreateuser','metadataowner','rpcdef','settingdef','settingparent','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)

pgsql-performance by date:

Previous
From: Tom Lane
Date:
Subject: Re: transaction ID wrap limit
Next
From: Tom Lane
Date:
Subject: Re: Query plan changing when queried data does not