huge runtime difference between 2 almost identical queries (was: Re: Index Scans become Seq Scans after VACUUM ANALYSE)

On Wed, Apr 17, 2002 at 12:44:24AM -0400, Tom Lane wrote:
> Louis-David Mitterrand <vindex(at)apartia(dot)org> writes:
> > While trying to optimise a query I found that running VACUUM ANALYSE
> > changed all the Index Scans to Seq Scans and that the only way to revert
> > to Index Scans was the add "enable_seqscan = 0" in postgresql.conf.
> >>
> >> EXPLAIN ANALYZE output would be more interesting than just EXPLAIN.
> >> Also, what does the pg_stats view show for these tables?
>
> > Thanks, pg_stats output is rather big so I attached it in a separate
> > file. Here are the EXPLAIN ANALYZE ouputs:
>
> Tell you the truth, I'm having a real hard time getting excited over
> a bug report that says the planner chose a plan taking 10.90 seconds
> in preference to one taking 7.96 seconds.

Now using a reduced test request I have a huge difference in runtime
(2317ms vs 4ms) on two almost identitcal queries. In both cases the
where clause uses the same table and pattern, however the slower query's
where-clause table appears at the end of the join:

gesci5=# explain analyse select p1.titre, p1.nom, p1.prenom, p2.titre, p2.nom, p2.prenom from personne p1 join prospect p on (p.id_personne1 = p1.id_personne) join personne p2 on (p.id_personne2 = p2.id_personne) join contact cn on (p.dernier_contact = cn.id_contact) where lower(p2.nom) like 'marl%' order by date_contact desc;
NOTICE: QUERY PLAN:

Sort (cost=5944.88..5944.88 rows=137 width=82) (actual time=2317.45..2317.45 rows=5 loops=1)
-> Nested Loop (cost=2168.52..5940.00 rows=137 width=82) (actual time=1061.58..2317.28 rows=5 loops=1)
-> Hash Join (cost=2168.52..5208.38 rows=137 width=70) (actual time=1061.23..2316.01 rows=5 loops=1)
-> Hash Join (cost=1406.52..4238.55 rows=27482 width=41) (actual time=355.60..2267.44 rows=27250 loops=1)
-> Seq Scan on personne p1 (cost=0.00..1102.00 rows=44100 width=29) (actual time=0.12..303.42 rows=44100 loops=1)
-> Hash (cost=1216.82..1216.82 rows=27482 width=12) (actual time=354.64..354.64 rows=0 loops=1)
-> Seq Scan on prospect p (cost=0.00..1216.82 rows=27482 width=12) (actual time=0.11..257.51 rows=27482 loops=1)
-> Hash (cost=761.45..761.45 rows=220 width=29) (actual time=0.33..0.33 rows=0 loops=1)
-> Index Scan using personne_nom on personne p2 (cost=0.00..761.45 rows=220 width=29) (actual time=0.07..0.29 rows=16 loops=1)
-> Index Scan using contact_pkey on contact cn (cost=0.00..5.31 rows=1 width=12) (actual time=0.22..0.23 rows=1 loops=5)
Total runtime: 2317.77 msec

EXPLAIN

gesci5=# explain analyse select p1.titre, p1.nom, p1.prenom, p2.titre, p2.nom, p2.prenom from personne p1 join prospect p on (p.id_personne1 = p1.id_personne) join personne p2 on (p.id_personne2 = p2.id_personne) join contact cn on (p.dernier_contact = cn.id_contact) where lower(p1.nom) like 'marl%' order by date_contact desc;
NOTICE: QUERY PLAN:

Sort (cost=3446.49..3446.49 rows=137 width=82) (actual time=3.85..3.85 rows=5 loops=1)
-> Nested Loop (cost=0.00..3441.61 rows=137 width=82) (actual time=1.86..3.55 rows=5 loops=1)
-> Nested Loop (cost=0.00..2709.99 rows=137 width=70) (actual time=1.81..3.32 rows=5 loops=1)
-> Nested Loop (cost=0.00..2018.40 rows=137 width=41) (actual time=0.58..2.41 rows=10 loops=1)
-> Index Scan using personne_nom on personne p1 (cost=0.00..761.45 rows=220 width=29) (actual time=0.30..0.55 rows=16 loops=1)
-> Index Scan using prospect_personne1 on prospect p (cost=0.00..5.69 rows=1 width=12) (actual time=0.10..0.11 rows=1 loops=16)
-> Index Scan using personne_pkey on personne p2 (cost=0.00..5.02 rows=1 width=29) (actual time=0.08..0.08 rows=0 loops=10)
-> Index Scan using contact_pkey on contact cn (cost=0.00..5.31 rows=1 width=12) (actual time=0.03..0.03 rows=1 loops=5)
Total runtime: 4.17 msec

--
PHEDRE: Il n'est plus temps. Il sait mes ardeurs insensées.
De l'austère pudeur les bornes sont passées.
(Phèdre, J-B Racine, acte 3, scène 1)