Re: Why does explain differ from explan analyze?

Hi Tom,

On Wed, 2006-12-06 at 14:48 -0500, Tom Lane wrote:
> Joost Kraaijeveld <J(dot)Kraaijeveld(at)Askesis(dot)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.88 rows=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=199996 width=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=3010 width=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.84 rows=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.82 rows=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.82 rows=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.044 rows=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=213 loops=1)
-> Hash Left Join (cost=18554.38..18867.49 rows=17 width=1387) (actual time=539.470..618.554 rows=213 loops=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=213 loops=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.155 rows=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.502 rows=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.05 rows=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.792 rows=15940 loops=1)
Sort Key: "t0_$deliver_cares".care_id
-> Bitmap Heap Scan on deliver_cares "t0_$deliver_cares" (cost=8015.77..18287.28 rows=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) (actual time=365.036..365.036 rows=0 loops=1)
-> Bitmap Index Scan on idx_deliver_cares_status (cost=0.00..1139.70 rows=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.99 rows=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.58 rows=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=994 loops=1)
-> Seq Scan on components "t2_$deliver_cares_care_component" (cost=0.00..25.84 rows=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=8 loops=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.82 rows=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.82 rows=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