Thread: Why does explain differ from explan analyze?

Why does explain differ from explan analyze?

From
Joost Kraaijeveld
Date:
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).

Is that possible, and if so, why? Does it have to do something with
vacuum?

TIA

--
Groeten,

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

Re: Why does explain differ from explan analyze?

From
Tom Lane
Date:
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?

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

            regards, tom lane

Re: Why does explain differ from explan analyze?

From
Joost Kraaijeveld
Date:
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

Re: Why does explain differ from explan analyze?

From
Tom Lane
Date:
Joost Kraaijeveld <J.Kraaijeveld@Askesis.nl> writes:
> 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?

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

Well, the answer is that these aren't the same query.  For instance
you've got a change in estimated rowcount for "cares":

>   ->  Seq Scan on cares "t1_$deliver_cares_care"  (cost=0.00..152.40 rows=3010 width=128)
>         Filter: ((workers_number = 1) AND ((status)::text <> 'S'::text))

>   ->  Index Scan using idx_cares7 on cares "t1_$deliver_cares_care"  (cost=0.00..176.05 rows=5147 width=128) (actual
time=0.111..8.450rows=4425 loops=1) 
>         Filter: ((workers_number = 1) AND ((status)::text <> 'P'::text))

and other changes elsewhere, all apparently due to using slightly
different constraint values.  That will (and should) affect the plan.

            regards, tom lane

Re: Why does explain differ from explan analyze?

From
Joost Kraaijeveld
Date:
On Thu, 2006-12-07 at 10:20 -0500, Tom Lane wrote:
> Well, the answer is that these aren't the same query.  For instance
You are right. I did not check the report thorough wnought. Sorry.


--
Groeten,

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