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=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
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Don't 'kill -9' the postmaster
>
>