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@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83


Fri, 14 Dec 2001 17:23:39 +0300 (GMT)
Oleg Bartunov <oleg@sai.msu.su>
7.2 cvs: explain analyze instabilities
When the first time query was executed, data was fetched by OS into memory
buffers. Second time, data was already in-memory.

And of course, vacuum updates statistics and gives different plan...

-alex

On Fri, 14 Dec 2001, Oleg Bartunov wrote:

> 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@sai.msu.su, http://www.sai.msu.su/~megera/
> phone: +007(095)939-16-83, +007(095)939-23-83
> 
> 
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster
> 
> 


Fri, 14 Dec 2001 09:51:35 -0500 (EST)
Alex Pilosov <alex@pilosoft.com>
Re: 7.2 cvs: explain analyze instabilities
Oleg Bartunov <oleg@sai.msu.su> writes:
> My question: does it normal that output of 'explain analyze' is unstable
> even if nothing was changed.

Certainly.  Buffering issues alone would cause actual runtime of a first
run to vary from subsequent runs.

			regards, tom lane

Fri, 14 Dec 2001 10:24:46 -0500
Tom Lane <tgl@sss.pgh.pa.us>
Re: 7.2 cvs: explain analyze instabilities 