Re: Why does explain differ from explan analyze? - Mailing list pgsql-general

Hi Tom,

On Wed, 2006-12-06 at 14:48 -0500, Tom Lane wrote:
> Joost Kraaijeveld <J.Kraaijeveld@Askesis.nl> writes:
> > I have a query that if I do "explain" shows an other plan than if I do
> > "explain analyze" with that same query (immediately after the explain).
>
> Really?  What PG version is this?  Can you provide a self-contained
> test case?
Yes, really ;-).

PostgreSQL 8.1.5 on Windows XP.

Alas, no self contained test case, I do have the query, the "explain"
and the "explain analyse" output. Sorry about the long text.

SELECT *
FROM   deliver_cares t0_$deliver_cares
LEFT   OUTER JOIN cares t1_$deliver_cares_care                          ON
t0_$deliver_cares.care_id=t1_$deliver_cares_care.care_id 
LEFT   OUTER JOIN components t2_$deliver_cares_care_component           ON
t1_$deliver_cares_care.component_id=t2_$deliver_cares_care_component.component_id 
LEFT   OUTER JOIN indication_functions t3_$deliver_cares_care_indicatio ON
t1_$deliver_cares_care.indication_function_id=t3_$deliver_cares_care_indicatio.indication_function_id 
LEFT   OUTER JOIN indications t4_$deliver_cares_care_indicatio          ON
t3_$deliver_cares_care_indicatio.indication_id=t4_$deliver_cares_care_indicatio.indication_id 
LEFT   OUTER JOIN patients t5_$deliver_cares_care_indicatio             ON
t4_$deliver_cares_care_indicatio.patient_id=t5_$deliver_cares_care_indicatio.patient_id 
LEFT   OUTER JOIN org_personnels t6_$deliver_cares_registeredOrgP       ON
t0_$deliver_cares.registered_org_personnel_id=t6_$deliver_cares_registeredOrgP.org_personnel_id 
LEFT   OUTER JOIN org_personnels t7_$deliver_cares_assignedOrgPer       ON
t0_$deliver_cares.assigned_org_personnel_id=t7_$deliver_cares_assignedOrgPer.org_personnel_id,timeframes
t1_pdam__$deliver_cares_timeframe 
WHERE  ((    (    (    (    (    (    (    (    (t4_$deliver_cares_care_indicatio.patient_id = 21)                   --
pdam
                                                 AND (t0_$deliver_cares.deliver_date >= current_date - 200)          --
pdam
                                            )
                                        AND (t0_$deliver_cares.deliver_date < current_date)                          --
pdam
                                       )
                                   AND (t0_$deliver_cares.timeframe_id = 45)                                         --
pdam
                                  )
                              AND (t1_$deliver_cares_care.workers_number = 1)                                        --
pdam
                             )
                         AND (t0_$deliver_cares.status = 'P')                                                        --
pdam
                        )
                    AND (t1_$deliver_cares_care.status <> 'S')                                                       --
pdam
                   )
               AND (t0_$deliver_cares.assigned_org_personnel_id IS NULL)
              )
          AND t0_$deliver_cares.care_id=t1_$deliver_cares_care.care_id
          AND t1_$deliver_cares_care.indication_function_id=t3_$deliver_cares_care_indicatio.indication_function_id
          AND t3_$deliver_cares_care_indicatio.indication_id=t4_$deliver_cares_care_indicatio.indication_id
       ))
AND    t0_$deliver_cares.timeframe_id=t1_pdam__$deliver_cares_timeframe.timeframe_id
ORDER  BY t0_$deliver_cares.deliver_date ASC
,         t1_pdam__$deliver_cares_timeframe.start_time ASC

explain:

--------------
Sort  (cost=38222.31..38222.49 rows=71 width=3089)
  Sort Key: "t0_$deliver_cares".deliver_date, "t1_pdam__$deliver_cares_timeframe".start_time
  ->  Nested Loop  (cost=1457.34..38220.13 rows=71 width=3089)
        ->  Seq Scan on timeframes "t1_pdam__$deliver_cares_timeframe"  (cost=0.00..1.25 rows=1 width=126)
              Filter: (timeframe_id = 45)
        ->  Nested Loop Left Join  (cost=1457.34..38218.17 rows=71 width=2963)
              ->  Nested Loop Left Join  (cost=1457.34..37803.85 rows=71 width=2175)
                    ->  Hash Left Join  (cost=1457.34..37389.53 rows=71 width=1387)
                          Hash Cond: ("outer".patient_id = "inner".patient_id)
                          ->  Hash Join  (cost=1451.54..37383.36 rows=71 width=486)
                                Hash Cond: ("outer".indication_function_id = "inner".indication_function_id)
                                ->  Hash Left Join  (cost=1438.21..37258.40 rows=22198 width=323)
                                      Hash Cond: ("outer".component_id = "inner".component_id)
                                      ->  Hash Join  (cost=1409.91..36897.13 rows=22198 width=233)
                                            Hash Cond: ("outer".care_id = "inner".care_id)
                                            ->  Bitmap Heap Scan on deliver_cares "t0_$deliver_cares"
(cost=1249.99..36124.88rows=39035 width=105) 
                                                  Recheck Cond: (timeframe_id = 45)
                                                  Filter: ((deliver_date >= (('now'::text)::date - 200)) AND
(deliver_date< ('now'::text)::date) AND ((status)::text = 'P'::text) AND (assigned_org_personnel_id IS NULL)) 
                                                  ->  Bitmap Index Scan on idx_deliver_cares2  (cost=0.00..1249.99
rows=199996width=0) 
                                                        Index Cond: (timeframe_id = 45)
                                            ->  Hash  (cost=152.40..152.40 rows=3010 width=128)
                                                  ->  Seq Scan on cares "t1_$deliver_cares_care"  (cost=0.00..152.40
rows=3010width=128) 
                                                        Filter: ((workers_number = 1) AND ((status)::text <>
'S'::text))
                                      ->  Hash  (cost=25.84..25.84 rows=984 width=90)
                                            ->  Seq Scan on components "t2_$deliver_cares_care_component"
(cost=0.00..25.84rows=984 width=90) 
                                ->  Hash  (cost=13.32..13.32 rows=5 width=163)
                                      ->  Nested Loop  (cost=0.00..13.32 rows=5 width=163)
                                            ->  Index Scan using idx_indications_patient_id on indications
"t4_$deliver_cares_care_indicatio" (cost=0.00..4.33 rows=2 width=97) 
                                                  Index Cond: (patient_id = 21)
                                            ->  Index Scan using idx_indication_functions1 on indication_functions
"t3_$deliver_cares_care_indicatio" (cost=0.00..4.45 rows=4 width=66) 
                                                  Index Cond: ("t3_$deliver_cares_care_indicatio".indication_id =
"outer".indication_id)
                          ->  Hash  (cost=5.80..5.80 rows=1 width=901)
                                ->  Index Scan using idx_patients_human_id_pk on patients
"t5_$deliver_cares_care_indicatio" (cost=0.00..5.80 rows=1 width=901) 
                                      Index Cond: (patient_id = 21)
                    ->  Index Scan using idx_org_personnels2 on org_personnels "t6_$deliver_cares_registeredorgp"
(cost=0.00..5.82rows=1 width=788) 
                          Index Cond: ("outer".registered_org_personnel_id =
"t6_$deliver_cares_registeredorgp".org_personnel_id)
              ->  Index Scan using idx_org_personnels2 on org_personnels "t7_$deliver_cares_assignedorgper"
(cost=0.00..5.82rows=1 width=788) 
                    Index Cond: ("outer".assigned_org_personnel_id =
"t7_$deliver_cares_assignedorgper".org_personnel_id)


explain analyse:
--------------
Sort  (cost=19067.67..19067.71 rows=17 width=3089) (actual time=634.660..634.746 rows=213 loops=1)
  Sort Key: "t0_$deliver_cares".deliver_date, "t1_pdam__$deliver_cares_timeframe".start_time
  ->  Nested Loop  (cost=18554.38..19067.32 rows=17 width=3089) (actual time=539.634..622.249 rows=213 loops=1)
        ->  Seq Scan on timeframes "t1_pdam__$deliver_cares_timeframe"  (cost=0.00..1.25 rows=1 width=126) (actual
time=0.034..0.044rows=1 loops=1) 
              Filter: (timeframe_id = 45)
        ->  Nested Loop Left Join  (cost=18554.38..19065.90 rows=17 width=2963) (actual time=539.572..621.726 rows=213
loops=1)
              ->  Nested Loop Left Join  (cost=18554.38..18966.69 rows=17 width=2175) (actual time=539.564..620.846
rows=213loops=1) 
                    ->  Hash Left Join  (cost=18554.38..18867.49 rows=17 width=1387) (actual time=539.470..618.554
rows=213loops=1) 
                          Hash Cond: ("outer".patient_id = "inner".patient_id)
                          ->  Hash Join  (cost=18548.57..18861.59 rows=17 width=486) (actual time=539.219..617.703
rows=213loops=1) 
                                Hash Cond: ("outer".indication_function_id = "inner".indication_function_id)
                                ->  Hash Left Join  (cost=18530.09..18825.31 rows=3528 width=323) (actual
time=530.610..608.155rows=15831 loops=1) 
                                      Hash Cond: ("outer".component_id = "inner".component_id)
                                      ->  Merge Join  (cost=18501.79..18744.09 rows=3528 width=233) (actual
time=528.732..577.502rows=15831 loops=1) 
                                            Merge Cond: ("outer".care_id = "inner".care_id)
                                            ->  Index Scan using idx_cares7 on cares "t1_$deliver_cares_care"
(cost=0.00..176.05rows=5147 width=128) (actual time=0.111..8.450 rows=4425 loops=1) 
                                                  Filter: ((workers_number = 1) AND ((status)::text <> 'P'::text))
                                            ->  Sort  (cost=18501.79..18510.86 rows=3628 width=105) (actual
time=528.570..541.792rows=15940 loops=1) 
                                                  Sort Key: "t0_$deliver_cares".care_id
                                                  ->  Bitmap Heap Scan on deliver_cares "t0_$deliver_cares"
(cost=8015.77..18287.28rows=3628 width=105) (actual time=366.358..444.921 rows=15940 loops=1) 
                                                        Recheck Cond: (((status)::text = 'D'::text) AND (timeframe_id =
45)AND (deliver_date >= (('now'::text)::date - 200)) AND (deliver_date < ('now'::text)::date)) 
                                                        Filter: (assigned_org_personnel_id IS NULL)
                                                        ->  BitmapAnd  (cost=8015.77..8015.77 rows=3628 width=0)
(actualtime=365.036..365.036 rows=0 loops=1) 
                                                              ->  Bitmap Index Scan on idx_deliver_cares_status
(cost=0.00..1139.70rows=182200 width=0) (actual time=67.510..67.510 rows=205223 loops=1) 
                                                                    Index Cond: ((status)::text = 'D'::text)
                                                              ->  Bitmap Index Scan on idx_deliver_cares2
(cost=0.00..1249.99rows=199996 width=0) (actual time=52.794..52.794 rows=182332 loops=1) 
                                                                    Index Cond: (timeframe_id = 45)
                                                              ->  Bitmap Index Scan on idx_deliver_cares_deliver_date
(cost=0.00..5625.58rows=643595 width=0) (actual time=240.958..240.958 rows=674086 loops=1) 
                                                                    Index Cond: ((deliver_date >= (('now'::text)::date
-200)) AND (deliver_date < ('now'::text)::date)) 
                                      ->  Hash  (cost=25.84..25.84 rows=984 width=90) (actual time=1.811..1.811
rows=994loops=1) 
                                            ->  Seq Scan on components "t2_$deliver_cares_care_component"
(cost=0.00..25.84rows=984 width=90) (actual time=0.054..1.024 rows=994 loops=1) 
                                ->  Hash  (cost=18.46..18.46 rows=8 width=163) (actual time=0.821..0.821 rows=8
loops=1)
                                      ->  Nested Loop  (cost=0.00..18.46 rows=8 width=163) (actual time=0.643..0.780
rows=8loops=1) 
                                            ->  Index Scan using idx_indications_patient_id on indications
"t4_$deliver_cares_care_indicatio" (cost=0.00..4.98 rows=3 width=97) (actual time=0.310..0.349 rows=3 loops=1) 
                                                  Index Cond: (patient_id = 12)
                                            ->  Index Scan using idx_indication_functions1 on indication_functions
"t3_$deliver_cares_care_indicatio" (cost=0.00..4.45 rows=4 width=66) (actual time=0.114..0.130 rows=3 loops=3) 
                                                  Index Cond: ("t3_$deliver_cares_care_indicatio".indication_id =
"outer".indication_id)
                          ->  Hash  (cost=5.80..5.80 rows=1 width=901) (actual time=0.205..0.205 rows=1 loops=1)
                                ->  Index Scan using idx_patients_human_id_pk on patients
"t5_$deliver_cares_care_indicatio" (cost=0.00..5.80 rows=1 width=901) (actual time=0.194..0.196 rows=1 loops=1) 
                                      Index Cond: (patient_id = 12)
                    ->  Index Scan using idx_org_personnels2 on org_personnels "t6_$deliver_cares_registeredorgp"
(cost=0.00..5.82rows=1 width=788) (actual time=0.005..0.006 rows=1 loops=213) 
                          Index Cond: ("outer".registered_org_personnel_id =
"t6_$deliver_cares_registeredorgp".org_personnel_id)
              ->  Index Scan using idx_org_personnels2 on org_personnels "t7_$deliver_cares_assignedorgper"
(cost=0.00..5.82rows=1 width=788) (actual time=0.001..0.001 rows=0 loops=213) 
                    Index Cond: ("outer".assigned_org_personnel_id =
"t7_$deliver_cares_assignedorgper".org_personnel_id)
Total runtime: 639.205 ms


> > Does it have to do something with vacuum?
>
> In theory an autovacuum happening between the two steps could update the
> statistics and cause the plan to change, but if it's repeatable then
> that hardly seems like the explanation.
It is repeatable, and no no vacuum is done.

--
Groeten,

Joost Kraaijeveld
Askesis B.V.
Molukkenstraat 14
6524NB Nijmegen
tel: 024-3888063 / 06-51855277
fax: 024-3608416
web: www.askesis.nl