Re: 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=226loops=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=3777loops=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=226loops=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=3777loops=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=3777loops=1)
 
>   ->  Index Scan using message_parts_mp on message_parts  (cost=0.00..102.57 rows=1 width=771) (actual
time=0.12..0.14rows=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
> 
>