Thread: Worse perfomance on 8.2.0 than on 7.4.14

Hi

I have a simple query which uses 32ms on 7.4.14 and 1015ms on 8.2.0.
I guess 7.4.14 creates a better execution plan than 8.2.0 for this query but
i don't know how to get it to select a better one.
Explain analyse output will be found near the end of the e-mail.

(I have simplified my real query to get it as simple as possible. The original query
contain 6 tables and was acceptable on 7.4.2, but took far too long on 8.1.4)

I have made a test setup to compare 7.4.14, 8.1.4 and 8.2.0.
8.1.4 and 8.2.0 uses the same execution plan and same time to execute.

postgresql.conf values i changed is
7.4.14
    Raised shared_buffers from 32MB to 128MB
    Raised temp_buffers from 8MB to 32MB
8.2.0
    Raised shared_buffers from 32MB to 128MB
    Raised temp_buffers from 8MB to 32MB
    Raised work_mem from 1MB to 8MB

(It did however not have any influence of speed for
the view_subset query shown below.)

vacuum analyze has been executed.

Computer:
    Dell PowerEdge 2950
    openSUSE Linux 10.1
    Intel(R) Xeon 3.00GHz
    4GB memory
    xfs filesystem on SAS disks

 Table "public.step_result_subset"
   Column    |  Type   | Modifiers
-------------+---------+-----------
 id          | integer | not null
 uut_result  | integer |
 step_parent | integer |
Indexes:
    "step_result_subset_pkey" PRIMARY KEY, btree (id)
    "step_result_subset_parent_key" btree (step_parent)
    "step_result_uut_result_idx" btree (uut_result)
Table contain 17 179 506 rows, and is ~400M when exported to file

             Table "public.uut_result_subset"
     Column      |            Type             | Modifiers
-----------------+-----------------------------+-----------
 id              | integer                     | not null
 start_date_time | timestamp without time zone |
Indexes:
    "uut_result_subset_pkey" PRIMARY KEY, btree (id)
    "uut_result_subset_start_date_time_idx" btree (start_date_time)
Table contain ~176 555 rows, and is ~4.7M when exportd to file

Query is defined as view:

create view view_subset as
select
  ur.id as ur_id,
  sr.id as sr_id
from
  uut_result_subset as ur
   inner join step_result_subset as sr
    on ur.id=sr.uut_result
where
  ur.start_date_time > '2006-12-11'
  and sr.step_parent=0;

Explain analyze is run several times to get a stable result
so i guess the numbers presented is with as much as possible
data in memory buffers.

Column step_result_subset.step_parent contain 0 in as many rows as there are rows in table uut_result_subset.
(In my data set this will be 176 500 rows, Other values for step_result_subset.step_parent is present 1003 times and
lower.)

Query: "select * from view_subset;" run against 7.4.14 server.
QUERY PLAN
------------------------------------------------------------------------
 Nested Loop  (cost=0.00..1400.86 rows=17 width=8) (actual time=0.161..26.287 rows=68 loops=1)
   ->  Index Scan using uut_result_subset_start_date_time_idx on uut_result_subset ur  (cost=0.00..63.28 rows=18
width=4)(actual time=0.052..0.195 rows=68 loops=1) 
         Index Cond: (start_date_time > '2006-12-11 00:00:00'::timestamp without time zone)
   ->  Index Scan using step_result_uut_result_idx on step_result_subset sr  (cost=0.00..74.28 rows=2 width=8) (actual
time=0.149..0.379rows=1 loops=68) 
         Index Cond: ("outer".id = sr.uut_result)
         Filter: (step_parent = 0)
 Total runtime: 26.379 ms

Query: "select * from view_subset;" run against 8.4.0 server.

QUERY PLAN
----------------------------------------------------------------------
 Hash Join  (cost=339.61..77103.61 rows=96 width=8) (actual time=5.249..1010.669 rows=68 loops=1)
   Hash Cond: (sr.uut_result = ur.id)
   ->  Index Scan using step_result_subset_parent_key on step_result_subset sr  (cost=0.00..76047.23 rows=143163
width=8)(actual time=0.082..905.326 rows=176449 loops=1) 
         Index Cond: (step_parent = 0)
   ->  Hash  (cost=339.31..339.31 rows=118 width=4) (actual time=0.149..0.149 rows=68 loops=1)
         ->  Bitmap Heap Scan on uut_result_subset ur  (cost=4.90..339.31 rows=118 width=4) (actual time=0.060..0.099
rows=68loops=1) 
               Recheck Cond: (start_date_time > '2006-12-11 00:00:00'::timestamp without time zone)
               ->  Bitmap Index Scan on uut_result_subset_start_date_time_idx  (cost=0.00..4.90 rows=118 width=0)
(actualtime=0.050..0.050 rows=68 loops=1) 
                     Index Cond: (start_date_time > '2006-12-11 00:00:00'::timestamp without time zone)
 Total runtime: 1010.775 ms

Thanks for tips.

Best regards
Rolf Østvik

> I have a simple query which uses 32ms on 7.4.14 and 1015ms on 8.2.0.
> I guess 7.4.14 creates a better execution plan than 8.2.0 for this query but
> i don't know how to get it to select a better one.
> Explain analyse output will be found near the end of the e-mail.
>
> Explain analyze is run several times to get a stable result
> so i guess the numbers presented is with as much as possible
> data in memory buffers.
>
> Query: "select * from view_subset;" run against 7.4.14 server.
> QUERY PLAN
> ------------------------------------------------------------------------
>  Nested Loop  (cost=0.00..1400.86 rows=17 width=8) (actual time=0.161..26.287 rows=68 loops=1)
>    ->  Index Scan using uut_result_subset_start_date_time_idx on uut_result_subset ur  (cost=0.00..63.28 rows=18
width=4)(actual time=0.052..0.195 rows=68 loops=1) 
>          Index Cond: (start_date_time > '2006-12-11 00:00:00'::timestamp without time zone)
>    ->  Index Scan using step_result_uut_result_idx on step_result_subset sr  (cost=0.00..74.28 rows=2 width=8)
(actualtime=0.149..0.379 rows=1 loops=68) 
>          Index Cond: ("outer".id = sr.uut_result)
>          Filter: (step_parent = 0)
>  Total runtime: 26.379 ms
>
> Query: "select * from view_subset;" run against 8.4.0 server.
>
> QUERY PLAN
> ----------------------------------------------------------------------
>  Hash Join  (cost=339.61..77103.61 rows=96 width=8) (actual time=5.249..1010.669 rows=68 loops=1)
>    Hash Cond: (sr.uut_result = ur.id)
>    ->  Index Scan using step_result_subset_parent_key on step_result_subset sr  (cost=0.00..76047.23 rows=143163
width=8)(actual time=0.082..905.326 rows=176449 loops=1) 
>          Index Cond: (step_parent = 0)
>    ->  Hash  (cost=339.31..339.31 rows=118 width=4) (actual time=0.149..0.149 rows=68 loops=1)
>          ->  Bitmap Heap Scan on uut_result_subset ur  (cost=4.90..339.31 rows=118 width=4) (actual time=0.060..0.099
rows=68loops=1) 
>                Recheck Cond: (start_date_time > '2006-12-11 00:00:00'::timestamp without time zone)
>                ->  Bitmap Index Scan on uut_result_subset_start_date_time_idx  (cost=0.00..4.90 rows=118 width=0)
(actualtime=0.050..0.050 rows=68 loops=1) 
>                      Index Cond: (start_date_time > '2006-12-11 00:00:00'::timestamp without time zone)
>  Total runtime: 1010.775 ms

Did you lower random_page_cost in 8.2 (which defaults to 4.0)? If not try 2.

regards
Claus

--- Claus Guttesen <kometen@gmail.com> skrev:

> > I have a simple query which uses 32ms on 7.4.14
> and 1015ms on 8.2.0.
> > I guess 7.4.14 creates a better execution plan
> than 8.2.0 for this query but
> > i don't know how to get it to select a better one.
> > Explain analyse output will be found near the end
> of the e-mail.
> >
> > Explain analyze is run several times to get a
> stable result
> > so i guess the numbers presented is with as much
> as possible
> > data in memory buffers.
> >
> > Query: "select * from view_subset;" run against
> 7.4.14 server.
> > QUERY PLAN
> >
>
------------------------------------------------------------------------
> >  Nested Loop  (cost=0.00..1400.86 rows=17 width=8)
> (actual time=0.161..26.287 rows=68 loops=1)
> >    ->  Index Scan using
> uut_result_subset_start_date_time_idx on
> uut_result_subset ur  (cost=0.00..63.28 rows=18
> width=4) (actual time=0.052..0.195 rows=68 loops=1)
> >          Index Cond: (start_date_time >
> '2006-12-11 00:00:00'::timestamp without time zone)
> >    ->  Index Scan using step_result_uut_result_idx
> on step_result_subset sr  (cost=0.00..74.28 rows=2
> width=8) (actual time=0.149..0.379 rows=1 loops=68)
> >          Index Cond: ("outer".id = sr.uut_result)
> >          Filter: (step_parent = 0)
> >  Total runtime: 26.379 ms
> >
> > Query: "select * from view_subset;" run against
> 8.4.0 server.
> >
> > QUERY PLAN
> >
>
----------------------------------------------------------------------
> >  Hash Join  (cost=339.61..77103.61 rows=96
> width=8) (actual time=5.249..1010.669 rows=68
> loops=1)
> >    Hash Cond: (sr.uut_result = ur.id)
> >    ->  Index Scan using
> step_result_subset_parent_key on step_result_subset
> sr  (cost=0.00..76047.23 rows=143163 width=8)
> (actual time=0.082..905.326 rows=176449 loops=1)
> >          Index Cond: (step_parent = 0)
> >    ->  Hash  (cost=339.31..339.31 rows=118
> width=4) (actual time=0.149..0.149 rows=68 loops=1)
> >          ->  Bitmap Heap Scan on uut_result_subset
> ur  (cost=4.90..339.31 rows=118 width=4) (actual
> time=0.060..0.099 rows=68 loops=1)
> >                Recheck Cond: (start_date_time >
> '2006-12-11 00:00:00'::timestamp without time zone)
> >                ->  Bitmap Index Scan on
> uut_result_subset_start_date_time_idx
> (cost=0.00..4.90 rows=118 width=0) (actual
> time=0.050..0.050 rows=68 loops=1)
> >                      Index Cond: (start_date_time
> > '2006-12-11 00:00:00'::timestamp without time
> zone)
> >  Total runtime: 1010.775 ms
>
> Did you lower random_page_cost in 8.2 (which
> defaults to 4.0)? If not try 2.

Thanks for the suggestion, but it was no change of
result.

> regards
> Claus


__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

On 31-Dec-06, at 6:33 AM, Rolf Østvik wrote:

>
> Hi
>
> I have a simple query which uses 32ms on 7.4.14 and 1015ms on 8.2.0.
> I guess 7.4.14 creates a better execution plan than 8.2.0 for this
> query but
> i don't know how to get it to select a better one.
> Explain analyse output will be found near the end of the e-mail.
>
> (I have simplified my real query to get it as simple as possible.
> The original query
> contain 6 tables and was acceptable on 7.4.2, but took far too long
> on 8.1.4)
>
> I have made a test setup to compare 7.4.14, 8.1.4 and 8.2.0.
> 8.1.4 and 8.2.0 uses the same execution plan and same time to execute.
>
> postgresql.conf values i changed is
> 7.4.14
>     Raised shared_buffers from 32MB to 128MB
>     Raised temp_buffers from 8MB to 32MB
> 8.2.0
>     Raised shared_buffers from 32MB to 128MB
>     Raised temp_buffers from 8MB to 32MB
>     Raised work_mem from 1MB to 8MB
>
set effective_cache to 3G
shared buffers should be 1G on this computer for 8.2

Dave
> (It did however not have any influence of speed for
> the view_subset query shown below.)
>
> vacuum analyze has been executed.
>
> Computer:
>     Dell PowerEdge 2950
>     openSUSE Linux 10.1
>     Intel(R) Xeon 3.00GHz
>     4GB memory
>     xfs filesystem on SAS disks
>
>  Table "public.step_result_subset"
>    Column    |  Type   | Modifiers
> -------------+---------+-----------
>  id          | integer | not null
>  uut_result  | integer |
>  step_parent | integer |
> Indexes:
>     "step_result_subset_pkey" PRIMARY KEY, btree (id)
>     "step_result_subset_parent_key" btree (step_parent)
>     "step_result_uut_result_idx" btree (uut_result)
> Table contain 17 179 506 rows, and is ~400M when exported to file
>
>              Table "public.uut_result_subset"
>      Column      |            Type             | Modifiers
> -----------------+-----------------------------+-----------
>  id              | integer                     | not null
>  start_date_time | timestamp without time zone |
> Indexes:
>     "uut_result_subset_pkey" PRIMARY KEY, btree (id)
>     "uut_result_subset_start_date_time_idx" btree (start_date_time)
> Table contain ~176 555 rows, and is ~4.7M when exportd to file
>
> Query is defined as view:
>
> create view view_subset as
> select
>   ur.id as ur_id,
>   sr.id as sr_id
> from
>   uut_result_subset as ur
>    inner join step_result_subset as sr
>     on ur.id=sr.uut_result
> where
>   ur.start_date_time > '2006-12-11'
>   and sr.step_parent=0;
>
> Explain analyze is run several times to get a stable result
> so i guess the numbers presented is with as much as possible
> data in memory buffers.
>
> Column step_result_subset.step_parent contain 0 in as many rows as
> there are rows in table uut_result_subset.
> (In my data set this will be 176 500 rows, Other values for
> step_result_subset.step_parent is present 1003 times and lower.)
>
> Query: "select * from view_subset;" run against 7.4.14 server.
> QUERY PLAN
> ----------------------------------------------------------------------
> --
>  Nested Loop  (cost=0.00..1400.86 rows=17 width=8) (actual
> time=0.161..26.287 rows=68 loops=1)
>    ->  Index Scan using uut_result_subset_start_date_time_idx on
> uut_result_subset ur  (cost=0.00..63.28 rows=18 width=4) (actual
> time=0.052..0.195 rows=68 loops=1)
>          Index Cond: (start_date_time > '2006-12-11
> 00:00:00'::timestamp without time zone)
>    ->  Index Scan using step_result_uut_result_idx on
> step_result_subset sr  (cost=0.00..74.28 rows=2 width=8) (actual
> time=0.149..0.379 rows=1 loops=68)
>          Index Cond: ("outer".id = sr.uut_result)
>          Filter: (step_parent = 0)
>  Total runtime: 26.379 ms
>
> Query: "select * from view_subset;" run against 8.4.0 server.
>
> QUERY PLAN
> ----------------------------------------------------------------------
>  Hash Join  (cost=339.61..77103.61 rows=96 width=8) (actual
> time=5.249..1010.669 rows=68 loops=1)
>    Hash Cond: (sr.uut_result = ur.id)
>    ->  Index Scan using step_result_subset_parent_key on
> step_result_subset sr  (cost=0.00..76047.23 rows=143163 width=8)
> (actual time=0.082..905.326 rows=176449 loops=1)
>          Index Cond: (step_parent = 0)
>    ->  Hash  (cost=339.31..339.31 rows=118 width=4) (actual
> time=0.149..0.149 rows=68 loops=1)
>          ->  Bitmap Heap Scan on uut_result_subset ur
> (cost=4.90..339.31 rows=118 width=4) (actual time=0.060..0.099
> rows=68 loops=1)
>                Recheck Cond: (start_date_time > '2006-12-11
> 00:00:00'::timestamp without time zone)
>                ->  Bitmap Index Scan on
> uut_result_subset_start_date_time_idx  (cost=0.00..4.90 rows=118
> width=0) (actual time=0.050..0.050 rows=68 loops=1)
>                      Index Cond: (start_date_time > '2006-12-11
> 00:00:00'::timestamp without time zone)
>  Total runtime: 1010.775 ms
>
> Thanks for tips.
>
> Best regards
> Rolf Østvik
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings
>

Rolf Østvik skrev:

> I have a simple query which uses 32ms on 7.4.14 and 1015ms on 8.2.0.
> I guess 7.4.14 creates a better execution plan than 8.2.0 for this query but


Try to turn off planner options in 8.2 to make it generate the same plan
as 7.4. Then run EXPLAIN ANALYZE on that query that generate the same
plan as in 7.4 and we can compare the costs and maybe understand what go
wrong.

For example, try

set enable_hashjoin to false;
set enable_bitmapscan to false;

but you might need to turn off more things to get it to generate the 7.4
plan.

/Dennis

Rolf =?iso-8859-1?q?=D8stvik?= <rolfostvik@yahoo.no> writes:
> I have a simple query which uses 32ms on 7.4.14 and 1015ms on 8.2.0.

There's something awfully strange about that 8.2 plan --- if it knew
that it'd have to scan all of uut_result_subset (which it should have
known, if the stats were up-to-date), why did it use an indexscan
rather than a seqscan?  Are you sure you haven't tweaked any parameters
you didn't tell us about, such as setting enable_seqscan = off?

            regards, tom lane

(I am sorry if my explain analyze outputs gets
garbled)

--- Dennis Bjorklund <db@zigo.dhs.org> skrev:

> Rolf Østvik skrev:
>
> > I have a simple query which uses 32ms on 7.4.14
> and 1015ms on 8.2.0.
> > I guess 7.4.14 creates a better execution plan
> than 8.2.0 for this query but
>
>
> Try to turn off planner options in 8.2 to make it
> generate the same plan
> as 7.4. Then run EXPLAIN ANALYZE on that query that
> generate the same
> plan as in 7.4 and we can compare the costs and
> maybe understand what go
> wrong.
>
> /Dennis
>

I have adjusted some settings in the postgresql.conf
file:
7.4.14
  shared_buffers=64000 #512MB
  sort_mem=32000       #32KB
  effective_cache_size=128000 #1GB
8.2.0
  shared_buffers=512MB
  temp_buffers=32MB
  work_mem=8MB
  effective_cache_size=1GB
  random_page_cost=2.0

And also disabled some planner options in 8.2
  enable_bitscanmap = off
  enable_hashjoin = off

NB: enable_seqscan = on (default value)

First i have some queries to give you a feel of size
of
datasets and plans and times.

Q-A: (Simple query A)
 select sr.id from step_result_subset as sr
  where sr.step_parent = 0;
Q-B: (Simple query B)
 select ur.id from uut_result_subset as ur
  where ur.start_date_time > '2006-12-11';
Q-C: (Simple query C)
 select ur.id from uut_result_subset as ur
  where ur.start_date_time > '2006-12-11';

7.4.14
Explain analyze of Q-A on 7.1.14:
 Index Scan using step_result_subset_parent_key on
step_result_subset sr  (cost=0.00..42793.67
rows=166069 width=4) (actual time=0.091..1201.073
rows=176449 loops=1)
   Index Cond: (step_parent = 0)
 Total runtime: 1263.592 ms
(3 rows)

Explain analyze of Q-B on 7.1.14:
 Index Scan using
uut_result_subset_start_date_time_idx on
uut_result_subset ur  (cost=0.00..63.28 rows=18
width=4) (actual time=0.081..0.190 rows=68 loops=1)
   Index Cond: (start_date_time > '2006-12-11
00:00:00'::timestamp without time zone)
 Total runtime: 0.242 ms
(3 rows)

Explain analyze of Q-C on 7.1.14:
 Seq Scan on uut_result_subset ur  (cost=0.00..3161.94
rows=28640 width=4) (actual time=0.059..108.159
rows=29144 loops=1)
   Filter: (start_date_time > '2006-09-11
00:00:00'::timestamp without time zone)
 Total runtime: 117.560 ms
(3 rows)

8.2.0
Explain analyze of Q-A on 8.2.0:
 Index Scan using step_result_subset_parent_key on
step_result_subset sr  (cost=0.00..26759.41
rows=143163 width=4) (actual time=0.099..924.039
rows=176449 loops=1)
   Index Cond: (step_parent = 0)
 Total runtime: 998.757 ms
(3 rows)

Explain analyze of Q-A on 8.2.0:
 Index Scan using
uut_result_subset_start_date_time_idx on
uut_result_subset ur  (cost=0.00..196.15 rows=118
width=4) (actual time=0.025..0.081 rows=68 loops=1)
   Index Cond: (start_date_time > '2006-12-11
00:00:00'::timestamp without time zone)
 Total runtime: 0.159 ms
(3 rows)

Explain analyze of Q-C on 8.2.0:
 Index Scan using
uut_result_subset_start_date_time_idx on
uut_result_subset ur  (cost=0.00..2382.39 rows=31340
width=4) (actual time=0.035..35.367 rows=29144
loops=1)
   Index Cond: (start_date_time > '2006-09-11
00:00:00'::timestamp without time zone)
 Total runtime: 47.168 ms
(3 rows)

Here is the complex query/view.
create view view_subset as
select
  ur.id as ur_id,
  sr.id as sr_id
from
  uut_result_subset as ur
   inner join step_result_subset as sr
    on ur.id=sr.uut_result
where
  ur.start_date_time > '2006-12-11'
  and sr.step_parent=0
;

Query with start_date_time > '2006-12-11' on 7.4.14
Query PLAN
---------------
 Nested Loop  (cost=0.00..1400.86 rows=17 width=8)
(actual time=0.066..12.754 rows=68 loops=1)
   ->  Index Scan using
uut_result_subset_start_date_time_idx on
uut_result_subset ur  (cost=0.00..63.28 rows=18
width=4) (actual time=0.019..0.136 rows=68 loops=1)
         Index Cond: (start_date_time > '2006-12-11
00:00:00'::timestamp without time zone)
   ->  Index Scan using step_result_uut_result_idx on
step_result_subset sr  (cost=0.00..74.28 rows=2
width=8) (actual time=0.085..0.182 rows=1 loops=68)
         Index Cond: ("outer".id = sr.uut_result)
         Filter: (step_parent = 0)
 Total runtime: 12.849 ms

Query with start_date_time > '2006-12-11' on 8.2.0
Query PLAN
---------------
 Nested Loop  (cost=0.00..35860.83 rows=96 width=8)
(actual time=11.891..2339.878 rows=68 loops=1)
   ->  Index Scan using step_result_subset_parent_key
on step_result_subset sr  (cost=0.00..26759.41
rows=143163 width=8) (actual time=0.083..1017.500
rows=176449 loops=1)
         Index Cond: (step_parent = 0)
   ->  Index Scan using uut_result_subset_pkey on
uut_result_subset ur  (cost=0.00..0.05 rows=1 width=4)
(actual time=0.006..0.006 rows=0 loops=176449)
         Index Cond: (ur.id = sr.uut_result)
         Filter: (start_date_time > '2006-12-11
00:00:00'::timestamp without time zone)
 Total runtime: 2339.974 ms

I also wanted to try it with a bigger dataset so i
set the restriction of start_date_time to
"start_date_time> '2006-09-11'"
I also then set "enable_hashjoin = on" to get same
plans on 7.4.14 and 8.2.0.

Query with start_date_time > '2006-09-11' on 7.4.14
Query PLAN
---------------
 Hash Join  (cost=3233.54..47126.96 rows=26940
width=8) (actual time=126.437..1489.584 rows=29139
loops=1)
   Hash Cond: ("outer".uut_result = "inner".id)
   ->  Index Scan using step_result_subset_parent_key
on step_result_subset sr  (cost=0.00..42793.67
rows=166069 width=8) (actual time=0.078..1137.123
rows=176449 loops=1)
         Index Cond: (step_parent = 0)
   ->  Hash  (cost=3161.94..3161.94 rows=28640
width=4) (actual time=126.068..126.068 rows=0 loops=1)
         ->  Seq Scan on uut_result_subset ur
(cost=0.00..3161.94 rows=28640 width=4) (actual
time=0.063..107.041 rows=29144 loops=1)
               Filter: (start_date_time > '2006-09-11
00:00:00'::timestamp without time zone)
 Total runtime: 1504.600 ms
(8 rows)

Query with start_date_time > '2006-09-11' on 8.2.0
Query PLAN
---------------
 Hash Join  (cost=2460.74..32695.45 rows=25413
width=8) (actual time=61.453..1198.048 rows=29139
loops=1)
   Hash Cond: (sr.uut_result = ur.id)
   ->  Index Scan using step_result_subset_parent_key
on step_result_subset sr  (cost=0.00..26759.41
rows=143163 width=8) (actual time=0.089..937.124
rows=176449 loops=1)
         Index Cond: (step_parent = 0)
   ->  Hash  (cost=2382.39..2382.39 rows=31340
width=4) (actual time=55.975..55.975 rows=29144
loops=1)
         ->  Index Scan using
uut_result_subset_start_date_time_idx on
uut_result_subset ur  (cost=0.00..2382.39 rows=31340
width=4) (actual time=0.051..35.635 rows=29144
loops=1)
               Index Cond: (start_date_time >
'2006-09-11 00:00:00'::timestamp without time zone)
 Total runtime: 1212.910 ms
(8 rows)

Other comments.
I am _beginning_ to get a feeling of adjusting
parameters and how my dataset behaves. 8.2.0 does (as
expected) work much better on bigger datasets than
7.4.14.
I was still hoping that i could get better response
times since i think the Q-C query
(ur.start_date_time > '2006-09-11') should be the
biggest restrictor of the datasets i want to look at.
From what i can understand that is what happens with
the query plan for 7.4.14 when restriction is
"ur.start_date_time > '2006-12-11'".

Best regards
Rolf Østvik

__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

--- Dave Cramer <pg@fastcrypt.com> skrev:

>
> On 31-Dec-06, at 6:33 AM, Rolf Østvik wrote:
>
> >
> > Hi
> >
> > I have a simple query which uses 32ms on 7.4.14
> and 1015ms on 8.2.0.
> > I guess 7.4.14 creates a better execution plan
> than 8.2.0 for this
> > query but
> > i don't know how to get it to select a better one.
> > Explain analyse output will be found near the end
> of the e-mail.
> >
> > (I have simplified my real query to get it as
> simple as possible.
> > The original query
> > contain 6 tables and was acceptable on 7.4.2, but
> took far too long
> > on 8.1.4)
> >
> > I have made a test setup to compare 7.4.14, 8.1.4
> and 8.2.0.
> > 8.1.4 and 8.2.0 uses the same execution plan and
> same time to execute.
> >
> > postgresql.conf values i changed is
> > 7.4.14
> >     Raised shared_buffers from 32MB to 128MB
> >     Raised temp_buffers from 8MB to 32MB
> > 8.2.0
> >     Raised shared_buffers from 32MB to 128MB
> >     Raised temp_buffers from 8MB to 32MB
> >     Raised work_mem from 1MB to 8MB
> >
> set effective_cache to 3G
> shared buffers should be 1G on this computer for 8.2

Thanks for the input. Did not have a big influence on
my specific problem but comments as this is very
valuable in the total setup of my server.

Best regards
Rolf Østvik

__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

--- Tom Lane <tgl@sss.pgh.pa.us> skrev:

> Rolf =?iso-8859-1?q?=D8stvik?= <rolfostvik@yahoo.no>
> writes:
> > I have a simple query which uses 32ms on 7.4.14
> and 1015ms on 8.2.0.
>
> There's something awfully strange about that 8.2
> plan --- if it knew
> that it'd have to scan all of uut_result_subset
> (which it should have
> known, if the stats were up-to-date),

I can't really see the need for it to do an sequence
scan, but that is me not knowing how things work.

>why did it use
> an indexscan
> rather than a seqscan?  Are you sure you haven't
> tweaked any parameters
> you didn't tell us about, such as setting
> enable_seqscan = off?

I haven't touched enable_seqscan.
It could be that i have forgotton to tell you about a
parameter i have tweaked, but i doubt it.

Best regards
Rolf Østvik

__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

=?iso-8859-1?q?Rolf=20=D8stvik?= <rolfostvik@yahoo.no> writes:
> First i have some queries to give you a feel of size
> of datasets and plans and times.

You said earlier that essentially all the rows of step_result_subset
have step_parent = 0 ... is that really true?  I can hardly believe
that either 7.4 or 8.2 would use an indexscan for Q-A if so.

I'd be interested to see the results of

prepare foo(int) as select id from step_result_subset sr
    where uut_result = $1 and step_parent = 0;
explain analyze execute foo(42);

(use some representative uut_result value instead of 42).  If it doesn't
want to use an indexscan for this, disable plan types until it does.
This would perhaps shed some light on why 8.2 doesn't want to use a scan
like that as the inside of a nestloop.

            regards, tom lane

--- Tom Lane <tgl@sss.pgh.pa.us> skrev:

> =?iso-8859-1?q?Rolf=20=D8stvik?=
> <rolfostvik@yahoo.no> writes:
> > First i have some queries to give you a feel of
> size
> > of datasets and plans and times.
>
> You said earlier that essentially all the rows of
> step_result_subset
> have step_parent = 0 ... is that really true?

Not true, but i am sorry if it could be intepreted
that way.
What i tried to say was
 step_result_subset contain 17 179 506 rows
 uut_Result_subset  contain    176 555 rows

There is one entry in step_result_subset with the
condition step_parent = 0 for each entry in
uut_result_subset (there is 176 555 rows in
step_result_subset which have step_parent = 0).

For this (sample) query i have found that if i select
just a little bigger data set (setting start_date_time
to an earlier date) the plan selected by the server
does the best job and gives a more stable execution
time independent of size of data sets. I also have
found that my theories of the best solution has been
wrong.


If you (Tom) still want me to do the following steps
then please tell me.

>  I can
> hardly believe
> that either 7.4 or 8.2 would use an indexscan for
> Q-A if so.
>
> I'd be interested to see the results of
>
> prepare foo(int) as select id from
> step_result_subset sr
>     where uut_result = $1 and step_parent = 0;
> explain analyze execute foo(42);
>
> (use some representative uut_result value instead of
> 42).  If it doesn't
> want to use an indexscan for this, disable plan
> types until it does.
> This would perhaps shed some light on why 8.2
> doesn't want to use a scan
> like that as the inside of a nestloop.
>
>             regards, tom lane
>

Best regards
Rolf Østvik


__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

=?iso-8859-1?q?Rolf=20=D8stvik?= <rolfostvik@yahoo.no> writes:
> If you (Tom) still want me to do the following steps
> then please tell me.

Please --- I'm still curious why the estimated cost changed so much from
7.4 to 8.2.  I can believe a marginal change in cost leading to a plan
switch, but comparing the total-cost numbers shows that 8.2 must think
that indexscan is a whole lot more expensive than 7.4 did, which seems
odd.  For the most part 8.2 ought to think nestloop-with-inner-indexscan
is cheaper than 7.4 did, because we now account for caching effects across
repeated iterations of the inner scan.

            regards, tom lane

--- Tom Lane <tgl@sss.pgh.pa.us> skrev:

>
> Please --- I'm still curious why the estimated cost changed so much from
> 7.4 to 8.2.  I can believe a marginal change in cost leading to a plan

Is this the output you need?

logistics_82=# prepare foo(int) as select id from step_result_subset where uut_Result = $1 and
step_parent = 0;
PREPARE
logistics_82=# explain analyze execute foo(180226);
QUERY PLAN
-----------------------------------------------
 Index Scan using step_result_uut_result_idx on step_result_subset  (cost=0.00..563.85 rows=23
width=4) (actual time=0.069..0.069 rows=0 loops=1)
   Index Cond: (uut_result = $1)
   Filter: (step_parent = 0)
 Total runtime: 0.112 ms
(4 rows)

Best regards,
Rolf Østvik

__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

=?iso-8859-1?q?Rolf=20=D8stvik?= <rolfostvik@yahoo.no> writes:
>  Index Scan using step_result_uut_result_idx on step_result_subset  (cost=0.00..563.85 rows=23
> width=4) (actual time=0.069..0.069 rows=0 loops=1)
>    Index Cond: (uut_result = $1)
>    Filter: (step_parent = 0)
>  Total runtime: 0.112 ms
> (4 rows)

Hm, that's interesting.  In your original message we have the following
for 7.4's estimate of the same plan step:

   ->  Index Scan using step_result_uut_result_idx on step_result_subset sr  (cost=0.00..74.28 rows=2 width=8) (actual
time=0.149..0.379rows=1 loops=68) 
         Index Cond: ("outer".id = sr.uut_result)
         Filter: (step_parent = 0)

The number-of-matching-rows estimate has gone up by a factor of 10,
which undoubtedly has a lot to do with the much higher cost estimate.
Do you have any idea why that is ... is the table really the same size
in both servers?  If so, could we see the pg_stats row for
step_result_subset.uut_result on both servers?

            regards, tom lane

--- Tom Lane <tgl@sss.pgh.pa.us> skrev:

> The number-of-matching-rows estimate has gone up by a factor of 10,
> which undoubtedly has a lot to do with the much higher cost estimate.
> Do you have any idea why that is ... is the table really the same size
> in both servers?  If so, could we see the pg_stats row for
> step_result_subset.uut_result on both servers?

Table step_result_subset and uut_result_subset in both databases is created from same schema
definition file and filled with data from the same data source file.

==== Server 7.4.14: ====

logistics_74# select count(*) from step_result_subset;
  count
----------
 17179506
(1 row)

logistics_74# select count(distinct uut_result) from step_result_subset;
 count
--------
 176450
(1 row)

logistics_74# analyse verbose step_result_subset;
INFO:  analyzing "public.step_result_subset"
INFO:  "step_result_subset": 92863 pages, 3000 rows sampled, 17179655 estimated total rows
ANALYZE

logistics_74# select * from pg_stats where tablename = step_result_subset and
attname='uut_result';
 schemaname |     tablename      |  attname   | null_frac | avg_width | n_distinct |
         most_common_vals                        |
most_common_freqs                                               |
histogram_bounds                             | correlation

------------+--------------------+------------+-----------+-----------+------------+----------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------+-------------
 public     | step_result_subset | uut_result |         0 |         4 |      57503 |
{70335,145211,17229,20091,21827,33338,34370,42426,47274,54146} |
{0.001,0.001,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667}
| {213,30974,51300,68529,85053,100838,114971,128126,144230,161657,176691} |    0.951364
(1 row)


==== Server 8.2.0: ====

logistics_82# select count(*) from step_result_subset;
  count
----------
 17179506
(1 row)

logistics_82# select count(distinct uut_result) from step_result_subset;
 count
--------
 176450
(1 row)

logistics_82# analyse verbose step_result_subset;
INFO:  analyzing "public.step_result_subset"
INFO:  "step_result_subset": scanned 3000 of 92863 pages, containing 555000 live rows and 0 dead
rows; 3000 rows in sample, 17179655 estimated total rows
ANALYZE

logistics_# select * from pg_stats where tablename = step_result_subset and attname='uut_result';
 schemaname |     tablename      |  attname   | null_frac | avg_width | n_distinct |
         most_common_vals                         |
most_common_freqs                                                |
histogram_bounds                             | correlation

------------+--------------------+------------+-----------+-----------+------------+-----------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------+-------------
 public     | step_result_subset | uut_result |         0 |         4 |       6516 |
{35010,111592,35790,41162,56844,57444,60709,73017,76295,106470} |
{0.00166667,0.00166667,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333}
| {147,31791,54286,70928,85996,102668,117885,130947,144766,162098,176685} |    0.954647
(1 row)

Then on server 8.2.0 i need to set statistics to ~120 on step_result_subset.uut_result to get
n_distinct to be in same range as n_distinct on 7.4.14.

Even with a statistics value of 1000, the n_distinct value does only reach ~138 000. Is it correct
that _ideally_ the n_distinct value should be the same as "select count(distinct uut_result) from
step_result_subset"?

====
Even with better statistics on step_result_subset.uut_result neither of 7.4.14 or 8.2.0 manages to
pick the best plan when i want to select bigger datasets (in my examples that would be to set an
earlier date in the where clause for "ur.start_date_time > '2006-12-11'"). I will continue to
adjust other parameters and see what i can manage myself.

Best regards
Rolf Østvik


__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com

On Fri, 2007-01-05 at 19:28 +0100, Rolf Østvik wrote:
> --- Tom Lane <tgl@sss.pgh.pa.us> skrev:
>
> > The number-of-matching-rows estimate has gone up by a factor of 10,
> > which undoubtedly has a lot to do with the much higher cost estimate.
> > Do you have any idea why that is ... is the table really the same size
> > in both servers?  If so, could we see the pg_stats row for
> > step_result_subset.uut_result on both servers?
>
> Table step_result_subset and uut_result_subset in both databases is created from same schema
> definition file and filled with data from the same data source file.
>
> ==== Server 7.4.14: ====
>
> logistics_74# select count(*) from step_result_subset;
>   count
> ----------
>  17179506
> (1 row)
>
> logistics_74# select count(distinct uut_result) from step_result_subset;
>  count
> --------
>  176450
> (1 row)
>
> logistics_74# analyse verbose step_result_subset;
> INFO:  analyzing "public.step_result_subset"
> INFO:  "step_result_subset": 92863 pages, 3000 rows sampled, 17179655 estimated total rows
> ANALYZE
>
> logistics_74# select * from pg_stats where tablename = step_result_subset and
> attname='uut_result';
>  schemaname |     tablename      |  attname   | null_frac | avg_width | n_distinct |
>          most_common_vals                        |
> most_common_freqs                                               |
> histogram_bounds                             | correlation
>
------------+--------------------+------------+-----------+-----------+------------+----------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------+-------------
>  public     | step_result_subset | uut_result |         0 |         4 |      57503 |
> {70335,145211,17229,20091,21827,33338,34370,42426,47274,54146} |
> {0.001,0.001,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667,0.000666667}
> | {213,30974,51300,68529,85053,100838,114971,128126,144230,161657,176691} |    0.951364
> (1 row)
>
>
> ==== Server 8.2.0: ====
>
> logistics_82# select count(*) from step_result_subset;
>   count
> ----------
>  17179506
> (1 row)
>
> logistics_82# select count(distinct uut_result) from step_result_subset;
>  count
> --------
>  176450
> (1 row)
>
> logistics_82# analyse verbose step_result_subset;
> INFO:  analyzing "public.step_result_subset"
> INFO:  "step_result_subset": scanned 3000 of 92863 pages, containing 555000 live rows and 0 dead
> rows; 3000 rows in sample, 17179655 estimated total rows
> ANALYZE
>
> logistics_# select * from pg_stats where tablename = step_result_subset and attname='uut_result';
>  schemaname |     tablename      |  attname   | null_frac | avg_width | n_distinct |
>          most_common_vals                         |
> most_common_freqs                                                |
> histogram_bounds                             | correlation
>
------------+--------------------+------------+-----------+-----------+------------+-----------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------+-------------
>  public     | step_result_subset | uut_result |         0 |         4 |       6516 |
> {35010,111592,35790,41162,56844,57444,60709,73017,76295,106470} |
> {0.00166667,0.00166667,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333,0.00133333}
> | {147,31791,54286,70928,85996,102668,117885,130947,144766,162098,176685} |    0.954647
> (1 row)
>
> Then on server 8.2.0 i need to set statistics to ~120 on step_result_subset.uut_result to get
> n_distinct to be in same range as n_distinct on 7.4.14.
>
> Even with a statistics value of 1000, the n_distinct value does only reach ~138 000. Is it correct
> that _ideally_ the n_distinct value should be the same as "select count(distinct uut_result) from
> step_result_subset"?

That is correct, as long as the number hasn't changed between the
ANALYZE and the select.

> Even with better statistics on step_result_subset.uut_result neither of 7.4.14 or 8.2.0 manages to
> pick the best plan when i want to select bigger datasets (in my examples that would be to set an
> earlier date in the where clause for "ur.start_date_time > '2006-12-11'"). I will continue to
> adjust other parameters and see what i can manage myself.

The ndistinct figure is very sensitive.

Could you re-run ANALYZE say 10 times each on the two release levels?
That will give you a better feel for the spread of likely values.

The distribution of rows with those values also makes a difference to
the results. ANALYZE assumes that all values are randomly distributed
within the table, so if the values are clumped together for whatever
reason the ndistinct calc is less likely to take that into account.

The larger sample size gained by increasing stats target does make a
difference.

--
  Simon Riggs
  EnterpriseDB   http://www.enterprisedb.com

--- Simon Riggs <simon@2ndquadrant.com> skrev:

>
> The distribution of rows with those values also makes a difference to
> the results. ANALYZE assumes that all values are randomly distributed
> within the table, so if the values are clumped together for whatever
> reason the ndistinct calc is less likely to take that into account.

This is an important factor.

As a summary, one table is defined like this:

Table "public.step_result_subset"
   Column    |  Type   | Modifiers
-------------+---------+-----------
 id          | integer | not null
 uut_result  | integer |
 step_parent | integer |
Indexes:
    "step_result_subset_pkey" PRIMARY KEY, btree (id)
    "step_result_subset_parent_key" btree (step_parent)
    "step_result_uut_result_idx" btree (uut_result)

The values in step_result_subset.uut_result is clumped together (between 10 and 1000 of same
value, and also increasing through the table).
The rows where step_result_subset.step_parent is 0 (a special case) is distributed within the
table.

Even when i set statistics on test_result_subset.uut_result to 1000 7.4.14 picks a better plan
than 8.2.0 for some returned datasets. The best results for both 7.4.14 and 8.2.0 is if i remove
the index step_result_subset_parent_key.
I will have to check if other queries which uses step_result_subset.step_parent will be "broken"
by removing the index but i think it should be ok.


I have gotten some ideas from this thread , read some more documentation, read the archives, and
tested other queries and will try to speed up some more advance queries.

Thanks everyone.

best regards
Rolf Østvik



__________________________________________________
Bruker du Yahoo!?
Lei av spam?  Yahoo! Mail har den beste spambeskyttelsen
http://no.mail.yahoo.com