We have a generated query from our web application which takes far longer to
complete in 9.0.4, than in 8.3.7 (>60sec in 9.0.4 ~10sec in 8.3.7)

The query plan generated in 9.0, includes a Materialize step which takes the
bulk of the time for the query. If I disable materialize (by running set
enable_material='off';) the query takes ~6 seconds to run (NOTE: the query
plan chosen in this case is very similar to the plan chosen in 8.3.7).
From reading
http://rhaas.blogspot.com/2010/04/materialization-in-postgresql-90.html, I
realize that the planner will be more aggressive in choosing Materialize in
9.0. Is there a way to modify the planner cost settings to minimize it's
use in cases like this?

Below, I have included the query in question and the "explain analyze"
output for the case where enable_material is on. .

NOTE: I will send explain analyze output for when enable_material is 'off'
and information on the postgresql version, settings and server configuration
in a follow up email due the length of email restrictions on the mailing
list.

(A vacuum analyze was run prior to running the queries for this email)

Any help that you can provide would be greatly appreciated.



Query
------------------------------------------------------------------------------------------------
SELECT *
FROM (
SELECT
Peter_SizeByType.RowId AS RowId,
Peter_SizeByType.Name AS Name,
Peter_SizeByType.Type AS Type,
Peter_SizeByType.ZAve AS ZAve,
Peter_SizeByType.TimeLabel AS TimeLabel,
Peter_SizeByType.StorageTemperature AS StorageTemperature,
Peter_SizeByType.Pdl AS Pdl,
Peter_SizeByType.Cumulants AS Cumulants,
Peter_SizeByType.AnalysisTool AS AnalysisTool,
Peter_SizeByType.meanCountRate AS meanCountRate,
Peter_SizeByType.ExtractionNumber AS ExtractionNumber,
Peter_SizeByType.TestNumber AS TestNumber,
Peter_SizeByType.Sort AS Sort
FROM (SELECT PS_2.rowid AS RowId,
F_3.Name AS Name,
F_3.Type AS Type,
PS_2.zave AS ZAve,
PS_2.timelabel AS TimeLabel,
PS_2.storagetemperature AS StorageTemperature,
PS_2.pdl AS Pdl,
PS_2.cumulants AS Cumulants,
PS_2.analysistool AS AnalysisTool,
PS_2.meancountrate AS meanCountRate,
PS_2.extractionnumber AS ExtractionNumber,
PS_2.testnumber AS TestNumber,
T_4.sort AS Sort
FROM (SELECT c69d129_particle_size_result_fields_5.analysistool AS
analysistool, c69d129_particle_size_result_fields_5.cumulants AS cumulants,
c69d129_particle_size_result_fields_5.extractionnumber AS extractionnumber,
c69d129_particle_size_result_fields_5.pdl AS pdl,
c69d129_particle_size_result_fields_5.rowid AS rowid,
(SELECT RunId FROM exp.Data WHERE RowId =
c69d129_particle_size_result_fields_5.DataId)
AS Run, c69d129_particle_size_result_fields_5$Run$.container AS
Run_Folder, c69d129_particle_size_result_fields_5$Run$Folder$.entityid AS
Run_Folder_EntityId, c69d129_particle_size_result_fields_5$Run$.name AS
Run_Name, c69d129_particle_size_result_fields_5.storagetemperature AS
storagetemperature, c69d129_particle_size_result_fields_5.testnumber AS
testnumber, c69d129_particle_size_result_fields_5.timelabel AS timelabel,
c69d129_particle_size_result_fields_5.zave AS zave,
c69d129_particle_size_result_fields_5.meancountrate AS meancountrate,
c69d129_particle_size_result_fields_5.rowid AS rowid1
FROM (SELECT * FROM assayresult."c69d129_particle_size_result_fields"
WHERE (((SELECT Container FROM exp.Data WHERE RowId = DataId) IN
('d938da12-1b43-102d-a8a2-78911b79dd1c'))))
c69d129_particle_size_result_fields_5
LEFT OUTER JOIN (SELECT * FROM exp.experimentrun
WHERE (((protocollsid LIKE
'urn:lsid:labkey.com:Particle+SizeProtocol.Folder-69:Particle+Size')))
AND (container IN ('d938da12-1b43-102d-a8a2-78911b79dd1c')))
c69d129_particle_size_result_fields_5$Run$ ON ((SELECT RunId FROM exp.Data
WHERE RowId = c69d129_particle_size_result_fields_5.DataId) =
c69d129_particle_size_result_fields_5$Run$.rowid)
LEFT OUTER JOIN core.containers
c69d129_particle_size_result_fields_5$Run$Folder$ ON
(c69d129_particle_size_result_fields_5$Run$.container =
c69d129_particle_size_result_fields_5$Run$Folder$.entityid)) PS_2
INNER JOIN (SELECT Formulations_6.container AS Folder,
Formulations_6$Folder$.entityid AS Folder_EntityId, Formulations_6.name AS
Name, Formulations_6.rowid AS RowId,
CAST((SELECT StringValue FROM exp.ObjectProperty WHERE
exp.ObjectProperty.PropertyId = 560 AND exp.ObjectProperty.ObjectId =
Formulations_6$LSID$_C.ObjectId) AS VARCHAR(4000))
AS Type
FROM (SELECT * FROM exp.material
WHERE (container IN ('d938da12-1b43-102d-a8a2-78911b79dd1c')) AND
((cpastype = 'urn:lsid:labkey.com:SampleSet.Folder-69:Formulations')))
Formulations_6
LEFT OUTER JOIN core.containers Formulations_6$Folder$ ON
(Formulations_6.container = Formulations_6$Folder$.entityid)
LEFT OUTER JOIN exp.object Formulations_6$LSID$_C ON
(Formulations_6.lsid = Formulations_6$LSID$_C.objecturi) AND
Formulations_6.Container = 'd938da12-1b43-102d-a8a2-78911b79dd1c') F_3 ON
PS_2.Run_Name=F_3.Name || '.xls' AND
PS_2.Run_Folder_EntityId=F_3.Folder_EntityId
INNER JOIN (SELECT
CAST((SELECT FloatValue FROM exp.ObjectProperty WHERE
exp.ObjectProperty.PropertyId = 1288 AND exp.ObjectProperty.ObjectId =
Timepoints_7.objectid) AS INT)
AS sort, Timepoints_7.key AS time
FROM (SELECT * FROM exp.indexvarchar
WHERE ((listid = 17))) Timepoints_7) T_4 ON PS_2.timelabel=T_4.time)
Peter_SizeByType ) x
ORDER BY Name ASC
LIMIT 101


Explain Analyze output with enable_material='on'
------------------------------------------------------------------------------------------------
Limit (cost=233190.18..233190.43 rows=101 width=71) (actual
time=194078.460..194078.645 rows=101 loops=1)
-> Sort (cost=233190.18..233190.44 rows=104 width=71) (actual
time=194078.457..194078.520 rows=101 loops=1)
Sort Key: material.name
Sort Method: top-N heapsort Memory: 39kB
-> Nested Loop Left Join (cost=3.27..233186.69 rows=104 width=71)
(actual time=3996.558..193952.126 rows=67044 loops=1)
Join Filter: ((material.container)::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text)
-> Nested Loop (cost=3.27..232216.91 rows=104 width=155)
(actual time=3996.433..190230.691 rows=67044 loops=1)
Join Filter: ((experimentrun.name)::text = ((
material.name)::text || '.xls'::text))
-> Index Scan using idx_material_lsid on material
(cost=0.00..444.90 rows=774 width=96) (actual time=0.251..14.974 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))
-> Materialize (cost=3.27..230512.55 rows=93
width=129) (actual time=0.023..70.942 rows=67044 loops=1303)
-> Nested Loop (cost=3.27..230512.08 rows=93
width=129) (actual time=0.065..3355.484 rows=67044 loops=1)
-> Nested Loop (cost=0.00..229803.99
rows=93 width=137) (actual time=0.048..2335.540 rows=67044 loops=1)
-> Nested Loop (cost=0.00..2.33
rows=1 width=74) (actual time=0.013..0.023 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.006..0.009 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.002..0.006 rows=1 loops=1)
Filter:
(("formulations_6$folder$".entityid)::text =
'd938da12-1b43-102d-a8a2-78911b79dd1c'::text)
-> Nested Loop
(cost=0.00..229800.73 rows=93 width=63) (actual time=0.032..2169.448
rows=67044 loops=1)
Join Filter:
((c69d129_particle_size_result_fields.timelabel)::text =
(indexvarchar.key)::text)
-> Seq Scan on
c69d129_particle_size_result_fields (cost=0.00..229742.02 rows=348
width=59) (actual time=0.016..527.225 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.003..0.004
rows=1 loops=69654)
Index Cond:
(rowid = $2)
-> Materialize
(cost=0.00..1.32 rows=11 width=10) (actual time=0.001..0.010 rows=11
loops=69654)
-> Seq Scan on
indexvarchar (cost=0.00..1.26 rows=11 width=10) (actual time=0.003..0.013
rows=11 loops=1)
Filter: (listid =
17)
-> Index Scan using pk_experimentrun on
experimentrun (cost=3.27..4.33 rows=1 width=74) (actual time=0.004..0.005
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-a8a
2-78911b79dd1c'::text))
SubPlan 4
-> Index Scan using pk_data on
data (cost=0.00..3.27 rows=1 width=4) (actual time=0.003..0.004 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.003..0.004 rows=1
loops=67044)
Index Cond: (rowid = $2)
-> Index Scan using uq_object on object
"formulations_6$lsid$_c" (cost=0.00..2.69 rows=1 width=64) (actual
time=0.033..0.034 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.007 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.004..0.005 rows=1
loops=67044)
Index Cond: ((objectid = $1) AND (propertyid = 1288))
Total runtime: 194080.893 ms


Thank you,

Brian Connolly

Search Discussions

  • Brian Connolly at May 5, 2011 at 7:55 pm
    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
  • Bosco Rama at May 5, 2011 at 8:01 pm
    Hey Brian,

    Brian Connolly wrote:
    (I had to send a follow up email due the length of email restrictions on the
    mailing list.)
    A tip for when you have this problem in the future -- turn off html mail.
    It will reduce your email message length by 50% - 90%.

    HTH

    Bosco.
  • Tom Lane at May 5, 2011 at 8:27 pm

    Brian Connolly writes:
    Any help that you can provide would be greatly appreciated.
    I'd suggest trying to get rid of the weird little subselects, like this
    one:
    ... SELECT * FROM assayresult."c69d129_particle_size_result_fields"
    WHERE (((SELECT Container FROM exp.Data WHERE RowId = DataId) IN
    ('d938da12-1b43-102d-a8a2-78911b79dd1c'))) ...
    If you turned that into a regular join between
    c69d129_particle_size_result_fields and Data, the planner probably
    wouldn't be nearly as confused about how many rows would result.
    It's the way-off rowcount estimate for this construct that's
    causing most of the problem, AFAICS:

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

    regards, tom lane

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouppgsql-performance @
categoriespostgresql
postedMay 5, '11 at 5:43p
activeMay 5, '11 at 8:27p
posts4
users3
websitepostgresql.org
irc#postgresql

People

Translate

site design / logo © 2021 Grokbase