7.2 cvs: explain analyze instabilities

Tom,

are there any reasons why 'explain analyze' produces different numbers ?

I just did dump/reload my test database and for the first time I get:

astronet=# explain analyze select *
astronet-# from
astronet-# messages,message_parts
astronet-# where messages.status_id in (5,8) AND (
astronet(# message_parts.fts_index @ '{65331}') AND message_parts.msg_id =
astronet-# messages.msg_id AND ( messages.sections &&
astronet(# '{1168509,1168511,1168513,1168516,1170263,300000001,300000003,300000004,300000005,300000006,300000007,300000008,300000009,300000010,300000011,300000012,300000013,300000014,300000015,300000016,300000017,300000027,300000028,300000029,300000030,300000031,300000032,300000033,300000034,300000036,300000037,300000038,300000039,300000040,300000041,300000042,300000043,300000044,300000045,300000046,300000047,300000048,300000049,300000050,300000051,300000052,300000053,300000054,300000055,300000056,300000057,300000058,300000059,300000060,300000061,300000062,300000063,300000064,300000065,300000066,300000067,300000068,300000069,300000070,300000071,300000074,300000075,300000077,300000078,300000079,300000080,300000081}');
NOTICE: QUERY PLAN:

Hash Join (cost=47.29..543.28 rows=1 width=812) (actual time=171.42..2594.08 rows=180 loops=1)
-> Index Scan using fts_idx on message_parts (cost=0.00..495.38 rows=124 width=148) (actual time=1.03..2335.54 rows=226 loops=1)
-> Hash (cost=47.28..47.28 rows=1 width=664) (actual time=169.95..169.95 rows=0 loops=1)
-> Index Scan using section_idx on messages (cost=0.00..47.28 rows=1 width=664) (actual time=0.35..155.83 rows=3777 loops=1)
Total runtime: 2596.59 msec

EXPLAIN

immediately repeat query (nothing changed):

astronet=# explain analyze select *
astronet-# from
astronet-# messages,message_parts
astronet-# where messages.status_id in (5,8) AND (
astronet(# message_parts.fts_index @ '{65331}') AND message_parts.msg_id =
astronet-# messages.msg_id AND ( messages.sections &&
astronet(# '{1168509,1168511,1168513,1168516,1170263,300000001,300000003,300000004,300000005,300000006,300000007,300000008,300000009,300000010,300000011,300000012,300000013,300000014,300000015,300000016,300000017,300000027,300000028,300000029,300000030,300000031,300000032,300000033,300000034,300000036,300000037,300000038,300000039,300000040,300000041,300000042,300000043,300000044,300000045,300000046,300000047,300000048,300000049,300000050,300000051,300000052,300000053,300000054,300000055,300000056,300000057,300000058,300000059,300000060,300000061,300000062,300000063,300000064,300000065,300000066,300000067,300000068,300000069,300000070,300000071,300000074,300000075,300000077,300000078,300000079,300000080,300000081}');
NOTICE: QUERY PLAN:

Hash Join (cost=47.29..543.28 rows=1 width=812) (actual time=182.29..448.05 rows=180 loops=1)
-> Index Scan using fts_idx on message_parts (cost=0.00..495.38 rows=124 width=148) (actual time=0.85..176.46 rows=226 loops=1)
-> Hash (cost=47.28..47.28 rows=1 width=664) (actual time=181.05..181.05 rows=0 loops=1)
-> Index Scan using section_idx on messages (cost=0.00..47.28 rows=1 width=664) (actual time=0.63..166.68 rows=3777 loops=1)
Total runtime: 448.85 msec

EXPLAIN

after 'vacuum full analyze' another plan:

astronet=# explain analyze select *
astronet-# from
astronet-# messages,message_parts
astronet-# where messages.status_id in (5,8) AND (
astronet(# message_parts.fts_index @ '{65331}') AND message_parts.msg_id =
astronet-# messages.msg_id AND ( messages.sections &&
astronet(# '{1168509,1168511,1168513,1168516,1170263,300000001,300000003,300000004,300000005,300000006,300000007,300000008,300000009,300000010,300000011,300000012,300000013,300000014,300000015,300000016,300000017,300000027,300000028,300000029,300000030,300000031,300000032,300000033,300000034,300000036,300000037,300000038,300000039,300000040,300000041,300000042,300000043,300000044,300000045,300000046,300000047,300000048,300000049,300000050,300000051,300000052,300000053,300000054,300000055,300000056,300000057,300000058,300000059,300000060,300000061,300000062,300000063,300000064,300000065,300000066,300000067,300000068,300000069,300000070,300000071,300000074,300000075,300000077,300000078,300000079,300000080,300000081}');
NOTICE: QUERY PLAN:

Nested Loop (cost=0.00..364.68 rows=1 width=1039) (actual time=37.10..740.14 rows=180 loops=1)
-> Index Scan using section_idx on messages (cost=0.00..47.28 rows=3 width=268) (actual time=0.34..175.43 rows=3777 loops=1)
-> Index Scan using message_parts_mp on message_parts (cost=0.00..102.57 rows=1 width=771) (actual time=0.12..0.14 rows=0 loops=3777)
Total runtime: 740.76 msec

EXPLAIN

I see 'fts_idx' not used anymore. section_idx and fts_idx are gist
indices (contrib/intarray), message_parts_mp is:
astronet=# \d message_parts_mp
Index "message_parts_mp"
Column | Type
---------+---------
msg_id | integer
part_id | integer
btree

My question: does it normal that output of 'explain analyze' is unstable
even if nothing was changed.

Also, I understand and we discussed that currently GiST doesn't provides
any useful information to optimizer but last explain somehow decided
to use 'section_idx' index but not use 'fts_idx' !

Regards,
Oleg
_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg(at)sai(dot)msu(dot)su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83