Why does explain differ from explan analyze?

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

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

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.450 rows=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

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