Thread

1. 7.2 cvs: explain analyze instabilities

   Oleg Bartunov <oleg@sai.msu.su> — 2001-12-14T14:23:39Z

   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
   
   
   

2. Re: 7.2 cvs: explain analyze instabilities

   Alex Pilosov <alex@pilosoft.com> — 2001-12-14T14:51:35Z

   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
   > 
   > 
   
   
   

3. Re: 7.2 cvs: explain analyze instabilities

   Tom Lane <tgl@sss.pgh.pa.us> — 2001-12-14T15:24:46Z

   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