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@engene.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@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@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-performance