Re: odd planner again, pg 9.0.8

Hello

you have too slow merge join

maybe you have bloated item_common_pkey or item_common relations -
can you try reindex or vacuum full

you use random_page_cost = 1.0 - it can be source of bad plan

Regards

Pavel Stehule

2012/7/25 Marcus Engene <mengpg2(at)engene(dot)se>:
> Hi,
>
> Lacking index hints I have a bit of a problem with a slow select.
>
> select
> pic.objectid as pic_objectid
> ,pu.objectid as pu_objectid
> ,ppcr.preproc_me as pul_preproc_me
> ,pp.price_amount as pp_price_amount
> ,pim.aut_item_container as pim_aut_item_container
> ,COALESCE((select coalesce(pcg.name_preferred, pcg.name) from codec_gfx
> pcg where pcg.objectid = pim.aut_codec_gfx), 'unknown') as pcg_name
> ,COALESCE((select pis.name from item_snd pis where pis.objectid =
> pim.aut_codec_snd), 'unknown') as pis_name
> -- ,(select pii2.price_arr from item_image pii2 where
> pii2.item_common = pic.objectid) as pii_price_arr
> ,pii.price_arr as pii_price_arr
> from
> (
> select
> ppcr.item_common
> ,pul.preproc_me as preproc_me
> ,pul.ul_finished_at as ul_finished_at
> ,pul.to_curator_at as to_curator_at
> from
> pic_curate ppc
> ,pic_curate_row ppcr
> ,uploading pul
> where
> ppc.user_curator = 2 AND
> ppcr.pic_curate = ppc.objectid AND
> ppcr.item_common = pul.item_common
> ) ppcr
> ,item_common pic
> left outer join item_movieclip pim on (pim.item_common = pic.objectid)
> left outer join item_soundclip pisc on (pisc.item_common =
> pic.objectid)
> left outer join item_image pii on (pii.item_common = pic.objectid)
> ,user pu
> ,pricing pp
> where
> pic.objectid = ppcr.item_common AND
> pu.objectid = pic.user AND
> pp.item_common = ppcr.item_common AND
> date_trunc ('sec', current_timestamp) BETWEEN pp.startdate and
> pp.stopdate
> order by
> ppcr.item_common
>
> Item_common is the main table. It has some 10M rows
>
> This query executes with...
>
> Nested Loop (cost=256.16..2770236.40 rows=3028 width=523) (actual
> time=0.141..64428.788 rows=919 l
> oops=1)
> -> Nested Loop (cost=256.16..2753774.01 rows=1066 width=515) (actual
> time=0.095..64414.614 rows=919 loops=1)
> -> Nested Loop (cost=256.16..2753472.18 rows=1066 width=501)
> (actual time=0.089..64411.782 rows=919 loops=1)
> -> Merge Join (cost=256.16..2750791.56 rows=1066 width=477)
> (actual time=0.080..64318.897 rows=919 loops=1)
> Merge Cond: (pic.objectid = ppcr.item_common)
> -> Merge Left Join (cost=251.72..2733545.74
> rows=10970452 width=473) (actual time=0.038..63075.673 rows=10831339
> loops=1)
> Merge Cond: (pic.objectid = pisc.item_common)
> -> Merge Left Join (cost=251.72..2689409.45
> rows=10970452 width=457) (actual time=0.031..59173.547 rows=10831339
> loops=1)
> Merge Cond: (pic.objectid =
> pii.item_common)
> -> Merge Left Join
> (cost=251.72..1844762.76 rows=10970452 width=404) (actual
> time=0.022..36763.334 rows=10831339 loops=1)
> Merge Cond: (pic.objectid =
> pim.item_common)
> -> Index Scan using item_common_pkey
> on item_common pic (cost=0.00..1764469.78 rows=10970452 width=380) (actual
> time=0.010..20389.141 rows=10831339 loops=1)
> -> Index Scan using
> item_movieclip_pkey on item_movieclip pim (cost=0.00..34287.89 rows=1486673
> width=28) (actual time=0.007..839.065 rows=1440175 loops=1)
> -> Index Scan using item_image_pkey on
> item_image pii (cost=0.00..707403.77 rows=8785343 width=57) (actual
> time=0.007..14972.056 rows=8701222 loops=1)
> -> Index Scan using item_soundclip_pkey on
> item_soundclip pisc (cost=0.00..10690.67 rows=481559 width=20) (actual
> time=0.007..252.650 rows=478672 loops=1)
> -> Materialize (cost=0.00..109.95 rows=1066 width=4)
> (actual time=0.019..1.792 rows=919 loops=1)
> -> Nested Loop (cost=0.00..107.28 rows=1066
> width=4) (actual time=0.018..1.429 rows=919 loops=1)
> Join Filter: (ppc.objectid =
> ppcr.pic_curate)
> -> Index Scan using pic_curate_row_pkey on
> pic_curate_row ppcr (cost=0.00..58.27 rows=3199 width=8) (actual
> time=0.010..0.650 rows=919 loops=1)
> -> Materialize (cost=0.00..1.03 rows=1
> width=4) (actual time=0.000..0.000 rows=1 loops=919)
> -> Seq Scan on pic_curate ppc
> (cost=0.00..1.02 rows=1 width=4) (actual time=0.005..0.006 rows=1 loops=1)
> Filter: (user_curator = 2)
> -> Index Scan using uploading_x2 on uploading pul
> (cost=0.00..2.50 rows=1 width=24) (actual time=0.100..0.100 rows=1
> loops=919)
> Index Cond: (pul.item_common = ppcr.item_common)
> -> Index Scan using user_pkey on user pu (cost=0.00..0.27 rows=1
> width=14) (actual time=0.002..0.002 rows=1 loops=919)
> Index Cond: (pu.objectid = pic.user)
> -> Index Scan using pricing_x1 on pricing pp (cost=0.00..3.55 rows=3
> width=16) (actual time=0.004..0.005 rows=1 loops=919)
> Index Cond: (pp.item_common = ppcr.item_common)
> Filter: ((date_trunc('sec'::text, now()) >= pp.startdate) AND
> (date_trunc('sec'::text, now()) <= pp.stopdate))
> SubPlan 1
> -> Index Scan using codec_gfx_pkey on codec_gfx pcg (cost=0.00..2.26
> rows=1 width=27) (actual time=0.000..0.000 rows=0 loops=919)
> Index Cond: (objectid = $0)
> SubPlan 2
> -> Seq Scan on item_snd pis (cost=0.00..1.90 rows=1 width=15) (actual
> time=0.007..0.008 rows=0 loops=919)
> Filter: (objectid = $1)
> Total runtime: 64429.074 ms
> (36 rows)
>
> ...but if I comment out pii...
>
> -- ,pii.price_arr as pii_price_arr
> ...
> -- left outer join item_image pii on (pii.item_common = pic.objectid)
>
> I get...
>
> Nested Loop (cost=0.00..9808.71 rows=1307 width=36) (actual
> time=0.073..23.335 rows=919 loops=1)
> -> Nested Loop (cost=0.00..2681.09 rows=460 width=32) (actual
> time=0.037..11.289 rows=919 loops=1)
> -> Nested Loop Left Join (cost=0.00..2550.85 rows=460 width=32)
> (actual time=0.033..9.001 rows=919 loops=1)
> -> Nested Loop (cost=0.00..2404.77 rows=460 width=20)
> (actual time=0.029..6.987 rows=919 loops=1)
> -> Nested Loop (cost=0.00..1226.38 rows=460 width=12)
> (actual time=0.025..4.065 rows=919 loops=1)
> -> Nested Loop (cost=0.00..50.26 rows=460
> width=4) (actual time=0.018..1.095 rows=919 loops=1)
> Join Filter: (ppc.objectid =
> ppcr.pic_curate)
> -> Index Scan using pic_curate_row_pkey on
> pic_curate_row ppcr (cost=0.00..35.45 rows=919 width=8) (actual
> time=0.008..0.360 rows=919 loops=1)
> -> Materialize (cost=0.00..1.03 rows=1
> width=4) (actual time=0.000..0.000 rows=1 loops=919)
> -> Seq Scan on pic_curate ppc
> (cost=0.00..1.02 rows=1 width=4) (actual time=0.005..0.005 rows=1 loops=1)
> Filter: (user_curator = 2)
> -> Index Scan using uploading_x2 on uploading
> pul (cost=0.00..2.54 rows=1 width=8) (actual time=0.002..0.003 rows=1
> loops=919)
> Index Cond: (pul.item_common =
> ppcr.item_common)
> -> Index Scan using item_common_pkey on item_common
> pic (cost=0.00..2.55 rows=1 width=8) (actual time=0.002..0.003 rows=1
> loops=919)
> Index Cond: (pic.objectid = ppcr.item_common)
> -> Index Scan using item_movieclip_pkey on item_movieclip
> pim (cost=0.00..0.31 rows=1 width=16) (actual time=0.002..0.002 rows=0
> loops=919)
> Index Cond: (pim.item_common = pic.objectid)
> -> Index Scan using user_pkey on user pu (cost=0.00..0.27 rows=1
> width=4) (actual time=0.002..0.002 rows=1 loops=919)
> Index Cond: (pu.objectid = pic.user)
> -> Index Scan using pricing_x1 on pricing pp (cost=0.00..3.63 rows=3
> width=12) (actual time=0.003..0.004 rows=1 loops=919)
> Index Cond: (pp.item_common = ppcr.item_common)
> Filter: ((date_trunc('sec'::text, now()) >= pp.startdate) AND
> (date_trunc('sec'::text, now()) <= pp.stopdate))
> SubPlan 1
> -> Index Scan using codec_gfx_pkey on codec_gfx pcg (cost=0.00..2.26
> rows=1 width=27) (actual time=0.000..0.000 rows=0 loops=919)
> Index Cond: (objectid = $0)
> SubPlan 2
> -> Seq Scan on item_snd pis (cost=0.00..1.90 rows=1 width=15) (actual
> time=0.007..0.008 rows=0 loops=919)
> Filter: (objectid = $1)
> Total runtime: 23.564 ms
> (29 rows)
>
> root(at)pg9:/usr/local/pgsql90/data# grep -v '^#' postgresql.conf | tr '\t' ' '
> | grep -v '^ ' | sort -u
> checkpoint_completion_target = 0.9 # checkpoint target duration, 0.0 - 1.0
> cpu_index_tuple_cost = 0.00001 # same scale as above
> datestyle = 'iso, mdy'
> default_text_search_config = 'pg_catalog.english'
> effective_cache_size = 32GB
> lc_messages = 'en_US.UTF-8' # locale for system error message
> lc_monetary = 'en_US.UTF-8' # locale for monetary formatting
> lc_numeric = 'en_US.UTF-8' # locale for number formatting
> lc_time = 'en_US.UTF-8' # locale for time formatting
> listen_addresses = 'localhost,10.0.0.3' # what IP address(es) to listen on;
> maintenance_work_mem = 2GB # min 1MB
> max_connections = 500 # (change requires restart)
> port = 5440 # (change requires restart)
> random_page_cost = 1.0 # same scale as above
> shared_buffers = 12GB # min 128kB
> temp_buffers = 64MB # min 800kB
> wal_buffers = 16MB # min 32kB
> work_mem = 64MB # min 64kB
>
> Without improvement i tried
> enable_seqscan = off
> cpu_index_tuple_cost = 0
> seq_page_cost = 2.0
>
> There are several selects looking similar to this in our application that
> suddenly jumped from a handfull of ms to many seconds. Can I workaround this
> by config instead of rewriting the sql to an inrecognizable nightmare?
> Preferrable I'd like to turn off full table scan completely (where indexes
> are present), but that didn't bite.
>
> Thanks,
> Marcus
>
>
> --
> Sent via pgsql-performance mailing list (pgsql-performance(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-performance