Re: Poor query plan chosen in 9.0.3 vs 8.3.7

Here is the explain analyze output for when enable_material is 'off' and
information on the postgresql version, settings and server configuration (I
had to send a follow up email due the length of email restrictions on the
mailing list.)

(I apologize for the length of these email messages. And if this message
does not get threaded properly as I did not receive a copy of my original
message to mailing list)

Explain Analyze output with enable_material='off'
------------------------------------------------------------------------------------------------

Limit (cost=231785.69..231785.94 rows=101 width=71) (actual
time=6616.943..6617.130 rows=101 loops=1)
-> Sort (cost=231785.69..231785.95 rows=104 width=71) (actual
time=6616.940..6617.003 rows=101 loops=1)
Sort Key: material.name
Sort Method: top-N heapsort Memory: 39kB
-> Nested Loop Left Join (cost=239.46..231782.21 rows=104
width=71) (actual time=3.840..6484.883 rows=67044 loops=1)
Join Filter: ((material.container)::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text)
-> Hash Join (cost=239.46..230812.42 rows=104 width=155)
(actual time=3.785..2676.643 rows=67044 loops=1)
Hash Cond: ((experimentrun.name)::text = ((
material.name)::text || '.xls'::text))
-> Nested Loop (cost=3.27..230557.06 rows=93
width=129) (actual time=0.170..2502.106 rows=67044 loops=1)
-> Nested Loop (cost=0.00..229848.97 rows=93
width=137) (actual time=0.153..1368.990 rows=67044 loops=1)
-> Nested Loop (cost=0.00..2.33 rows=1
width=74) (actual time=0.016..0.025 rows=1 loops=1)
-> Seq Scan on containers
"c69d129_particle_size_result_fields_5$run$folder$" (cost=0.00..1.16 rows=1
width=37) (actual time=0.010..0.013 rows=1 loops=1)
Filter: ((entityid)::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text)
-> Seq Scan on containers
"formulations_6$folder$" (cost=0.00..1.16 rows=1 width=37) (actual
time=0.003..0.007 rows=1 loops=1)
Filter:
(("formulations_6$folder$".entityid)::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text)
-> Nested Loop (cost=0.00..229845.71
rows=93 width=63) (actual time=0.133..1244.558 rows=67044 loops=1)
-> Seq Scan on
c69d129_particle_size_result_fields (cost=0.00..229742.02 rows=348
width=59) (actual time=0.018..572.402 rows=69654 loops=1)
Filter: (((SubPlan 3))::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text)
SubPlan 3
-> Index Scan using pk_data
on data (cost=0.00..3.27 rows=1 width=37) (actual time=0.004..0.005 rows=1
loops=69654)
Index Cond: (rowid =
$2)
-> Index Scan using pk_indexvarchar
on indexvarchar (cost=0.00..0.29 rows=1 width=10) (actual time=0.004..0.006
rows=1 loops=69654)
Index Cond:
((indexvarchar.listid = 17) AND ((indexvarchar.key)::text =
(c69d129_particle_size_result_fields.timelabel)::text))
-> Index Scan using pk_experimentrun on
experimentrun (cost=3.27..4.33 rows=1 width=74) (actual time=0.005..0.006
rows=1 loops=67044)
Index Cond: (experimentrun.rowid = (SubPlan
4))
Filter:
(((experimentrun.protocollsid)::text ~~
'urn:lsid:labkey.com:Particle+SizeProtocol.Folder-69:Particle+Size'::text)
AND ((experimentrun.container)::text = 'd938da12-1b43-102d-a8a2-7891
1b79dd1c'::text))
SubPlan 4
-> Index Scan using pk_data on data
(cost=0.00..3.27 rows=1 width=4) (actual time=0.004..0.005 rows=1
loops=67044)
Index Cond: (rowid = $2)
SubPlan 4
-> Index Scan using pk_data on data
(cost=0.00..3.27 rows=1 width=4) (actual time=0.004..0.005 rows=1
loops=67044)
Index Cond: (rowid = $2)
-> Hash (cost=226.51..226.51 rows=774 width=96)
(actual time=3.587..3.587 rows=1303 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 158kB
-> Seq Scan on material (cost=0.00..226.51
rows=774 width=96) (actual time=0.071..2.354 rows=1303 loops=1)
Filter: (((container)::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text) AND ((cpastype)::text =
'urn:lsid:labkey.com:SampleSet.Folder-69:Formulations'::text))
-> Index Scan using uq_object on object
"formulations_6$lsid$_c" (cost=0.00..2.69 rows=1 width=64) (actual
time=0.035..0.036 rows=1 loops=67044)
Index Cond: ((material.lsid)::text =
("formulations_6$lsid$_c".objecturi)::text)
SubPlan 1
-> Index Scan using pk_objectproperty on objectproperty
(cost=0.00..3.31 rows=1 width=13) (actual time=0.005..0.006 rows=1
loops=67044)
Index Cond: ((objectid = $0) AND (propertyid = 560))
SubPlan 2
-> Index Scan using pk_objectproperty on objectproperty
(cost=0.00..3.31 rows=1 width=8) (actual time=0.003..0.004 rows=1
loops=67044)
Index Cond: ((objectid = $1) AND (propertyid = 1288))
Total runtime: 6617.360 ms

Other Information
------------------------------------------------------------------------------------------------

- Version: PostgreSQL 9.0.3 on x86_64-unknown-linux-gnu, compiled by GCC
gcc (Ubuntu 4.4.3-4ubuntu5) 4.4.3, 64-bit
- Operating System: Ubuntu 10.04 LTS
- uname -a = Linux hostname 2.6.32-305-ec2 #9-Ubuntu SMP Thu Apr 15
08:05:38 UTC 2010 x86_64 GNU/Linux
- Server Information
- 4 cores
- 8GB of RAM
- PostgreSQL Configuration Information
- max_connections = 50
- shared_buffers = 2048MB
- work_mem = 20MB
- maintenance_work_mem = 1024MB
- wal_buffers = 4MB
- checkpoint_segments = 10
- checkpoint_timeout = 15min
- random_page_cost = 1.5 and 4.0 (tested with both default and
non-default)
- effective_cache_size = 6144MB
- join_collapse_limit = 10
- autovacuum = on
- All other settings default
- Vacuum and Analyze is run nightly.

Thank you for any help you might be able to provide.

Brian Connolly