Thread: two queries and dual cpu (perplexed)

two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
Hi everybody,

One of our clients was using SQL-Server and decided to switch to
PostgreSQL 8.0.1.

Hardware: Dual processor  Intel(R) Xeon(TM) CPU 3.40GHz
OS: Enterprise Linux with 2.6.9-5 SMP kernel
Filesystem: ext3
SHMMAX: $ cat  /proc/sys/kernel/shmmax
6442450944 <--- beleive that's ~6.5 GB, total ram is 8GB
Database: 15GB in size with a few tables with over 80 million rows.

Here is a snippit from the output of
SELECT oid , relname, relpages, reltuples
        FROM pg_class ORDER BY relpages DESC;
    oid    |             relname             | relpages |  reltuples
-----------+---------------------------------+----------+-------------
     16996 | CurrentAusClimate               |   474551 | 8.06736e+07
     16983 | ClimateChangeModel40            |   338252 | 5.31055e+07
 157821816 | PK_CurrentAusClimate            |   265628 | 8.06736e+07
 157835995 | idx_climateid                   |   176645 | 8.06736e+07
 157835996 | idx_ausposnum                   |   176645 | 8.06736e+07
 157835997 | idx_climatevalue              |   176645 | 8.06736e+07
 157821808 | PK_ClimateModelChange_40        |   174858 | 5.31055e+07
 157821788 | IX_iMonth001                    |   116280 | 5.31055e+07
 157821787 | IX_ClimateId                    |   116280 | 5.31055e+07
 157821786 | IX_AusPosNumber                 |   116280 | 5.31055e+07
     17034 | NeighbourhoodTable              |    54312 | 1.00476e+07
 157821854 | PK_NeighbourhoodTable           |    27552 | 1.00476e+07
 157821801 | IX_NeighbourhoodId              |    22002 | 1.00476e+07
 157821800 | IX_NAusPosNumber                |    22002 | 1.00476e+07
 157821799 | IX_AusPosNumber006              |    22002 | 1.00476e+07
[...]

To test the performance of the database we ran one of the most demanding
queries that exist with the following embarrassing results:

Query Execution time on:
SQL-Server (dual processor xeon)  3min 11sec
PostgreSQL (SMP IBM Linux server) 5min 30sec

Now I have not touch the $PGDATA/postgresql.conf (As I know very little
about memory tuning) Have run VACCUM & ANALYZE.

The client understands that they may not match the performance for a
single query as there is no multithreading. So they asked me to
demonstrate the benefits of Postgresql's multiprocessing capabilities.

To do that I modified the most demanding query to create a second query
and ran them in parallel:

$ time ./run_test1.sh
$ cat ./run_test1.sh
/usr/bin/time -p psql -f ./q1.sql ausclimate > q1.out 2>q1.time &
/usr/bin/time -p psql -f ./q2.sql ausclimate > q2.out 2>q2.time

and the time taken is *twice* that for the original. The modification was
minor. The queries do make use of both CPUs:

 2388 postgres 16 0 79640 15m 11m R 80.9 0.2 5:05.81 postmaster
 2389 postgres 16 0 79640 15m 11m R 66.2 0.2 5:04.25 postmaster

But I can't understand why there's no performance improvement and infact
there seems to be no benefit of multiprocessing.  Any ideas? I don't know
enough about the locking procedures employed by postgres but one would
think this shouldn't be and issue with read-only queries.

Please don't hesitate to ask me for more info like, the query or the
output of explain, or stats on memory usage. I just wanted to keep this
short and provide more info as the cogs start turning :-)

Thanks & Regards
Shoaib



Re: two queries and dual cpu (perplexed)

From
Jeff
Date:
On Apr 21, 2005, at 7:49 AM, Shoaib Burq (VPAC) wrote:

> Now I have not touch the $PGDATA/postgresql.conf (As I know very little
> about memory tuning) Have run VACCUM & ANALYZE.
>
You should really, really bump up shared_buffers and given you have 8GB
of ram this query would likely benefit from more work_mem.

> and the time taken is *twice* that for the original. The modification
> was
> minor. The queries do make use of both CPUs:
>
Is this an IO intensive query?  If running both in parellel results in
2x the run time and you have sufficient cpus it would (to me) indicate
you don't have enough IO bandwidth to satisfy the query.

Can we see an explain analyze of the query?  Could be a bad plan and a
bad plan will never give good performance.

--
Jeff Trout <jeff@jefftrout.com>
http://www.jefftrout.com/
http://www.stuarthamm.net/


Re: two queries and dual cpu (perplexed)

From
Gavin Sherry
Date:
On Thu, 21 Apr 2005, Jeff wrote:

>
> On Apr 21, 2005, at 7:49 AM, Shoaib Burq (VPAC) wrote:
>
> > Now I have not touch the $PGDATA/postgresql.conf (As I know very little
> > about memory tuning) Have run VACCUM & ANALYZE.
> >
> You should really, really bump up shared_buffers and given you have 8GB
> of ram this query would likely benefit from more work_mem.

I'd recommend shared_buffers = 10600. Its possible that work_mem in the
hundreds of megabytes might have a good impact, but its hard to say
without seeing the EXPLAIN ANALYZE output.

Gavin


Re: two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
here's explain sorry about the mess: I can attach it as text-file if you
like.

ausclimate=# explain ANALYZE  select count(*) from "getfutureausclimate";



QUERY PLAN
     

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=1069345.85..1069345.85 rows=1 width=0) (actual
time=443241.241..443241.242 rows=1 loops=1)
   ->  Subquery Scan getfutureausclimate  (cost=1069345.61..1069345.81
rows=16 width=0) (actual time=411449.034..436165.259 rows=13276368
loops=1)
         ->  Sort  (cost=1069345.61..1069345.65 rows=16 width=58) (actual
time=411449.026..426001.199 rows=13276368 loops=1)
               Sort Key: "Aus40_DEM"."AusPosNumber",
"CurrentAusClimate"."iMonth"
               ->  Nested Loop  (cost=2.19..1069345.29 rows=16 width=58)
(actual time=135.390..366902.373 rows=13276368 loops=1)
                     ->  Nested Loop  (cost=2.19..1067304.07 rows=44
width=68) (actual time=107.627..186390.137 rows=13276368 loops=1)
                           ->  Nested Loop  (cost=2.19..1067038.94 rows=44
width=52) (actual time=87.255..49743.796 rows=13276368 loops=1)
                                 ->  Nested Loop  (cost=2.19..8.09 rows=1
width=32) (actual time=52.684..52.695 rows=1 loops=1)
                                       ->  Merge Join  (cost=2.19..2.24
rows=1 width=24) (actual time=28.000..28.007 rows=1 loops=1)
                                             Merge Cond:
("outer"."ClimateId" = "inner"."ClimateId")
                                             ->  Sort  (cost=1.17..1.19
rows=7 width=10) (actual time=10.306..10.307 rows=3 loops=1)
                                                   Sort Key:
"ClimateVariables"."ClimateId"
                                                   ->  Seq Scan on
"ClimateVariables"  (cost=0.00..1.07 rows=7 width=10) (actual
time=10.277..10.286 rows=7 loops=1)
                                             ->  Sort  (cost=1.02..1.02
rows=1 width=14) (actual time=17.679..17.680 rows=1 loops=1)
                                                   Sort Key:
"GetFutureClimateParameters"."ClimateId"
                                                   ->  Seq Scan on
"GetFutureClimateParameters"  (cost=0.00..1.01 rows=1 width=14) (actual
time=17.669..17.671 rows=1 loops=1)
                                       ->  Index Scan using
"PK_ScenarioEmissionLevels" on "ScenarioEmissionLevels"  (cost=0.00..5.83
rows=1 width=18) (actual time=24.676..24.679 rows=1 loops=1)
                                             Index Cond:
(("ScenarioEmissionLevels"."ScenarioId" = "outer"."ScenarioId") AND
("ScenarioEmissionLevels"."iYear" = "outer"."iYear") AND
("ScenarioEmissionLevels"."LevelId" = "outer"."LevelId"))
                                 ->  Index Scan using "IX_ClimateId" on
"ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20)
(actual time=34.564..19435.855 rows=13276368 loops=1)
                                       Index Cond: ("outer"."ClimateId" =
"ClimateChangeModel40"."ClimateId")
                           ->  Index Scan using "PK_Aus40_DEM" on
"Aus40_DEM"  (cost=0.00..6.01 rows=1 width=16) (actual time=0.005..0.006
rows=1 loops=13276368)
                                 Index Cond: ("outer"."AusPosNumber" =
"Aus40_DEM"."AusPosNumber")
                     ->  Index Scan using "PK_CurrentAusClimate" on
"CurrentAusClimate"  (cost=0.00..46.20 rows=11 width=14) (actual
time=0.007..0.009 rows=1 loops=13276368)
                           Index Cond: (("CurrentAusClimate"."ClimateId" =
"outer"."ClimateId") AND ("outer"."AusPosNumber" =
"CurrentAusClimate"."AusPosNum") AND ("CurrentAusClimate"."iMonth" =
"outer"."iMonth"))
 Total runtime: 443983.269 ms
(25 rows)


Sheeeesshh...

> You should really, really bump up shared_buffers and given you have 8GB
> of ram this query would likely benefit from more work_mem.

I actually tried that and there was a decrease in performance. Are the
shared_buffers and work_mem the only things I should change to start with?
If so what's the reasoning.


> Is this an IO intensive query?  If running both in parellel results in
> 2x the run time and you have sufficient cpus it would (to me) indicate
> you don't have enough IO bandwidth to satisfy the query.

Yes I think so too: ... I am just compiling some io stats...

Also will jump on to irc...

>
Whoa! thanks all... I am overwhelmed with the help I am getting... I love
it!



Re: two queries and dual cpu (perplexed)

From
Russell Smith
Date:
On Thu, 21 Apr 2005 10:44 pm, Shoaib Burq (VPAC) wrote:
>   ->  Nested Loop  (cost=2.19..1069345.29 rows=16 width=58) (actual time=135.390..366902.373 rows=13276368 loops=1)
>                      ->  Nested Loop  (cost=2.19..1067304.07 rows=44 width=68) (actual time=107.627..186390.137
rows=13276368loops=1) 
>                            ->  Nested Loop  (cost=2.19..1067038.94 rows=44 width=52) (actual time=87.255..49743.796
rows=13276368loops=1) 

OUCH, OUCH, OUCH.

Most if not all of the time is going on nested loop joins.  The tuple estimates are off by a factore of 10^6 which is
meansit's chosing the wrong 
join type.

you could set enable_seqscan to OFF;  to test what he performance is like with a different plan, and then set it back
on.

However you really need to get the row count estimates up to something comparable.  within a factor of 10 at least.
A number of the other rows estimates seem to be off by a reasonable amount too.  You may want to bump up the statistics
onthe relevant 
columns.  I can't find what they are from looking at that, I probably should be able too, but it's late.

If you get the stats up to something near the real values, then the planner will choose a different plan, which should
givea huge performance 
increase.

Regards

Russell Smith.


Re: two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
here are some i/o stats with the unchanged postgresql.conf. Gonna change
it now and have another go.


[postgres@dbsql1 MultiCPU_test]$ vmstat 10
procs -----------memory---------- ---swap-- -----io---- --system--
----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy
id wa
 0  0  25808 710356 6348860 972052    2    4    73    29    1     3  1  0
99  0
 2  0  25808 647636 6348960 1034784    0    0  3226  3048 1054 92819 55 19
25  1
 2  0  25808 585684 6349032 1096660    0    0  3203  3057 1053 96375 55 19
25  1
 2  0  25808 521940 6349112 1160364    0    0  3388  2970 1052 95563 54 19
26  1
 2  0  25808 463636 6349184 1218568    0    0  2804  3037 1048 93560 55 19
25  1
 2  0  25808 405460 6349264 1276696    0    0  2794  3047 1046 96971 55 19
25  1
 2  0  25808 343956 6349340 1338160    0    0  3151  3040 1049 96629 55 20
25  1
 2  0  25808 287252 6349412 1394732    0    0  2666  2990 1045 95173 54 20
25  1
 2  0  25808 230804 6349484 1451168    0    0  2678  2966 1044 95577 54 19
26  1
 2  0  25808 169428 6349560 1512428    0    0  3164  3015 1048 98451 55 19
25  1
 2  0  25808 110484 6349640 1571304    0    0  2910  2970 1050 98214 55 20
25  0
 0  0  25808  50260 6349716 1631408    0    0  3049  3015 1049 99830 55 20
25  1
 1  0  25808   8512 6349788 1673156    0    0  2934  2959 1047 95940 54 19
24  3
 2  1  25808   8768 6349796 1672944    0    0  2552  2984 1043 97893 55 19
18  8
 1  1  25808   8384 6349824 1673256    0    0  2596  3032 1051 94646 55 19
19  6
 2  1  25808   8960 6349856 1672680    0    0  2982  3028 1052 94486 55 20
19  6
 1  1  25808   8960 6349884 1672584    0    0  3125  2919 1052 86969 52 20
19  8
 2  0  25808   6196 6349912 1675276    0    0  2809  3064 1046 99147 55 20
19  5
 1  1  25808   9216 6349976 1672152    0    0  2898  3076 1047 93271 55 19
21  6
 2  0  25808   6580 6349316 1663972    0    0  3150  2982 1048 94964 54 22
20  4
 2  0  25808   7692 6349348 1674480    0    0  2742  3006 1045 97488 54 21
21  4
 2  1  25808   8232 6346244 1676700    0    0  2900  3022 1048 92496 54 20
19  8
 2  0  25808   7104 6346192 1678044    0    0  3284  2958 1057 97265 55 20
18  7
 2  0  25808   8488 6346168 1676776    0    0  2609  3031 1047 93965 55 19
20  7
 2  1  25808   8680 6346184 1676488    0    0  3067  3044 1051 96594 55 19
19  6
 2  0  25808   8576 6346168 1676640    0    0  2900  3070 1047 96300 55 19
20  6
 2  1  25808   9152 6346156 1676176    0    0  3010  2993 1049 98271 55 20
19  7
 2  0  25808   7040 6346172 1678200    0    0  3242  3034 1050 97669 55 20
21  4
 1  1  25808   8900 6346192 1676344    0    0  2859  3014 1052 91220 53 19
21  6
 2  1  25808   8512 6346188 1676824    0    0  2737  2960 1049 100609 55
20 18  6
 2  0  25808   7204 6346236 1678000    0    0  2972  3045 1050 94851 55 19
17  9
 1  0  25808   7116 6346208 1678028    0    0  3053  2996 1048 98901 55 19
20  5
 2  1  25808   9180 6346196 1676068    0    0  2857  3067 1047 100629 56
21 20  3
procs -----------memory---------- ---swap-- -----io---- --system--
----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy
id wa
 3  1  25808   8896 6346172 1676500    0    0  3138  3022 1049 97937 55 20
20  5
 2  1  25808   9088 6346188 1676212    0    0  2844  3022 1047 97664 55 19
20  5
 1  1  25808   8920 6346248 1676288    0    0  3017  3024 1049 99644 55 20
17  7
 1  1  25808   8064 6346116 1677168    0    0  2824  3037 1047 99171 55 20
19  5
 2  1  25820   8472 6344336 1678596    0    0  2969  2957 1047 96396 54 21
18  7
 2  1  25820   9208 6344300 1677884    0    0  3072  3031 1050 95017 54 19
22  5
 1  0  25820   7848 6344328 1679148    0    0  3229  3011 1050 97108 55 19
20  5
 2  1  25820   8960 6344348 1678040    0    0  2701  2954 1046 98485 54 20
21  5
 2  0  25820   7900 6344368 1679244    0    0  2604  2931 1044 97198 54 20
19  7
 2  0  25820   9240 6344424 1677896    0    0  2990  3015 1048 102414 56
20 19  5
 2  0  25820   8924 6344436 1678088    0    0  3256  2991 1049 96709 55 19
21  5
 1  1  25820   8900 6344456 1678204    0    0  2761  3030 1051 96498 55 20
20  5
 2  0  25820   7628 6344440 1679444    0    0  2952  3012 1053 96534 55 20
19  6
 2  0  25820   7080 6344472 1679956    0    0  2848  3079 1050 95074 56 19
19  6
 2  0  25820   8928 6344444 1678080    0    0  2985  3021 1049 96806 55 20
18  7
 2  1  25820   7976 6344976 1676892   11    0  3429  3062 1083 92817 55 19
18  8
 2  0  25820   8096 6345080 1676652    0    0  2662  2989 1056 91921 54 19
17 10
 1  0  25820   7424 6345128 1677352    0    0  2956  3029 1054 99385 56 19
20  5
 2  0  25820   6664 6345232 1677724    0    0  3358  3030 1064 95929 55 19
21  5
 1  0  25820   7268 6345320 1676956    0    0  2681  3012 1082 97744 54 20
18  7
 2  0  25820   6944 6345364 1677184    0    0  3156  3022 1061 98055 55 19
22  4
 2  0  25820   8668 6345420 1675428    0    0  2990  3018 1050 94734 55 19
22  5
 2  1  25820   8724 6345464 1675452    0    0  2677  2967 1055 100760 55
20 18  7
 2  1  25820   9260 6345508 1674796    0    0  3296  3233 1054 99711 55 20
20  5
 2  0  25820   6196 6345556 1677944    0    0  2861  2950 1066 93289 53 19
23  6
 2  0  25820   8052 6345620 1675908    0    0  3012  2920 1051 94428 54 19
20  7
 2  1  25820   9000 6345672 1675040    0    0  2645  2980 1045 99992 56 20
17  8
 2  1  25820   8296 6345728 1675732    0    0  3216  3058 1052 91934 54 19
21  5
 2  0  25820   7900 6345796 1676072    0    0  3009  3022 1052 96303 55 19
20  7
 2  0  25820   8516 6345844 1675344    0    0  2586  2956 1048 95812 54 20
19  8
 2  1  25820   9000 6345892 1674752    0    0  3225  3028 1055 99786 54 20
21  5
 0  1  25820   9128 6345768 1674684    0    1  2868  3016 1049 98301 55 21
19  6
 2  1  25820   8160 6345828 1675576    0    0  3079  3056 1050 93725 55 19
21  5




On Thu, 21 Apr 2005, Shoaib Burq (VPAC) wrote:

>
> here's explain sorry about the mess: I can attach it as text-file if you
> like.
>
> ausclimate=# explain ANALYZE  select count(*) from "getfutureausclimate";
>
>
>
> QUERY PLAN
       
>
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>  Aggregate  (cost=1069345.85..1069345.85 rows=1 width=0) (actual
> time=443241.241..443241.242 rows=1 loops=1)
>    ->  Subquery Scan getfutureausclimate  (cost=1069345.61..1069345.81
> rows=16 width=0) (actual time=411449.034..436165.259 rows=13276368
> loops=1)
>          ->  Sort  (cost=1069345.61..1069345.65 rows=16 width=58) (actual
> time=411449.026..426001.199 rows=13276368 loops=1)
>                Sort Key: "Aus40_DEM"."AusPosNumber",
> "CurrentAusClimate"."iMonth"
>                ->  Nested Loop  (cost=2.19..1069345.29 rows=16 width=58)
> (actual time=135.390..366902.373 rows=13276368 loops=1)
>                      ->  Nested Loop  (cost=2.19..1067304.07 rows=44
> width=68) (actual time=107.627..186390.137 rows=13276368 loops=1)
>                            ->  Nested Loop  (cost=2.19..1067038.94 rows=44
> width=52) (actual time=87.255..49743.796 rows=13276368 loops=1)
>                                  ->  Nested Loop  (cost=2.19..8.09 rows=1
> width=32) (actual time=52.684..52.695 rows=1 loops=1)
>                                        ->  Merge Join  (cost=2.19..2.24
> rows=1 width=24) (actual time=28.000..28.007 rows=1 loops=1)
>                                              Merge Cond:
> ("outer"."ClimateId" = "inner"."ClimateId")
>                                              ->  Sort  (cost=1.17..1.19
> rows=7 width=10) (actual time=10.306..10.307 rows=3 loops=1)
>                                                    Sort Key:
> "ClimateVariables"."ClimateId"
>                                                    ->  Seq Scan on
> "ClimateVariables"  (cost=0.00..1.07 rows=7 width=10) (actual
> time=10.277..10.286 rows=7 loops=1)
>                                              ->  Sort  (cost=1.02..1.02
> rows=1 width=14) (actual time=17.679..17.680 rows=1 loops=1)
>                                                    Sort Key:
> "GetFutureClimateParameters"."ClimateId"
>                                                    ->  Seq Scan on
> "GetFutureClimateParameters"  (cost=0.00..1.01 rows=1 width=14) (actual
> time=17.669..17.671 rows=1 loops=1)
>                                        ->  Index Scan using
> "PK_ScenarioEmissionLevels" on "ScenarioEmissionLevels"  (cost=0.00..5.83
> rows=1 width=18) (actual time=24.676..24.679 rows=1 loops=1)
>                                              Index Cond:
> (("ScenarioEmissionLevels"."ScenarioId" = "outer"."ScenarioId") AND
> ("ScenarioEmissionLevels"."iYear" = "outer"."iYear") AND
> ("ScenarioEmissionLevels"."LevelId" = "outer"."LevelId"))
>                                  ->  Index Scan using "IX_ClimateId" on
> "ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20)
> (actual time=34.564..19435.855 rows=13276368 loops=1)
>                                        Index Cond: ("outer"."ClimateId" =
> "ClimateChangeModel40"."ClimateId")
>                            ->  Index Scan using "PK_Aus40_DEM" on
> "Aus40_DEM"  (cost=0.00..6.01 rows=1 width=16) (actual time=0.005..0.006
> rows=1 loops=13276368)
>                                  Index Cond: ("outer"."AusPosNumber" =
> "Aus40_DEM"."AusPosNumber")
>                      ->  Index Scan using "PK_CurrentAusClimate" on
> "CurrentAusClimate"  (cost=0.00..46.20 rows=11 width=14) (actual
> time=0.007..0.009 rows=1 loops=13276368)
>                            Index Cond: (("CurrentAusClimate"."ClimateId" =
> "outer"."ClimateId") AND ("outer"."AusPosNumber" =
> "CurrentAusClimate"."AusPosNum") AND ("CurrentAusClimate"."iMonth" =
> "outer"."iMonth"))
>  Total runtime: 443983.269 ms
> (25 rows)
>
>
> Sheeeesshh...
>
> > You should really, really bump up shared_buffers and given you have 8GB
> > of ram this query would likely benefit from more work_mem.
>
> I actually tried that and there was a decrease in performance. Are the
> shared_buffers and work_mem the only things I should change to start with?
> If so what's the reasoning.
>
>
> > Is this an IO intensive query?  If running both in parellel results in
> > 2x the run time and you have sufficient cpus it would (to me) indicate
> > you don't have enough IO bandwidth to satisfy the query.
>
> Yes I think so too: ... I am just compiling some io stats...
>
> Also will jump on to irc...
>
> >
> Whoa! thanks all... I am overwhelmed with the help I am getting... I love
> it!
>
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: you can get off all lists at once with the unregister command
>     (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
>

--
Shoaib Burq
--
VPAC - Geospatial Applications Developer
Building 91, 110 Victoria Street,
Carlton South, Vic 3053, Australia
_______________________________________________________________
w: www.vpac.org  | e: sab_AT_vpac_DOT_org | mob: +61.431-850039



Re: two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
> Is this an IO intensive query?  If running both in parellel results in
> 2x the run time and you have sufficient cpus it would (to me) indicate
> you don't have enough IO bandwidth to satisfy the query.

any tips on how to verify this?


Re: two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
Just tried it with the following changes:

shared_buffers = 10600
work_mem = 102400
enable_seqscan = false

still no improvement

Ok here's the Plan with the enable_seqscan = false:
ausclimate=# explain ANALYZE  select count(*) from "getfutureausclimate";

QUERY PLAN
     

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=101069350.74..101069350.74 rows=1 width=0) (actual
time=461651.787..461651.787 rows=1 loops=1)
   ->  Subquery Scan getfutureausclimate  (cost=101069350.50..101069350.70
rows=16 width=0) (actual time=426142.382..454571.397 rows=13276368
loops=1)
         ->  Sort  (cost=101069350.50..101069350.54 rows=16 width=58)
(actual time=426142.375..444428.278 rows=13276368 loops=1)
               Sort Key: "Aus40_DEM"."AusPosNumber",
"CurrentAusClimate"."iMonth"
               ->  Nested Loop  (cost=100000001.02..101069350.18 rows=16
width=58) (actual time=72.740..366588.646 rows=13276368 loops=1)
                     ->  Nested Loop  (cost=100000001.02..101067308.96
rows=44 width=68) (actual time=35.788..184032.873 rows=13276368 loops=1)
                           ->  Nested Loop
(cost=100000001.02..101067043.83 rows=44 width=52) (actual
time=35.753..47971.652 rows=13276368 loops=1)
                                 ->  Nested Loop
(cost=100000001.02..100000012.98 rows=1 width=32) (actual
time=7.433..7.446 rows=1 loops=1)
                                       ->  Merge Join
(cost=100000001.02..100000007.13 rows=1 width=24) (actual
time=7.403..7.412 rows=1 loops=1)
                                             Merge Cond:
("outer"."ClimateId" = "inner"."ClimateId")
                                             ->  Index Scan using
"PK_ClimateVariables" on "ClimateVariables"  (cost=0.00..6.08 rows=7
width=10) (actual time=0.011..0.015 rows=3 loops=1)
                                             ->  Sort
(cost=100000001.02..100000001.03 rows=1 width=14) (actual
time=7.374..7.375 rows=1 loops=1)
                                                   Sort Key:
"GetFutureClimateParameters"."ClimateId"
                                                   ->  Seq Scan on
"GetFutureClimateParameters"  (cost=100000000.00..100000001.01 rows=1
width=14) (actual time=7.361..7.362 rows=1 loops=1)
                                       ->  Index Scan using
"PK_ScenarioEmissionLevels" on "ScenarioEmissionLevels"  (cost=0.00..5.83
rows=1 width=18) (actual time=0.021..0.024 rows=1 loops=1)
                                             Index Cond:
(("ScenarioEmissionLevels"."ScenarioId" = "outer"."ScenarioId") AND
("ScenarioEmissionLevels"."iYear" = "outer"."iYear") AND
("ScenarioEmissionLevels"."LevelId" = "outer"."LevelId"))
                                 ->  Index Scan using "IX_ClimateId" on
"ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20)
(actual time=28.311..17212.703 rows=13276368 loops=1)
                                       Index Cond: ("outer"."ClimateId" =
"ClimateChangeModel40"."ClimateId")
                           ->  Index Scan using "PK_Aus40_DEM" on
"Aus40_DEM"  (cost=0.00..6.01 rows=1 width=16) (actual time=0.005..0.006
rows=1 loops=13276368)
                                 Index Cond: ("outer"."AusPosNumber" =
"Aus40_DEM"."AusPosNumber")
                     ->  Index Scan using "PK_CurrentAusClimate" on
"CurrentAusClimate"  (cost=0.00..46.20 rows=11 width=14) (actual
time=0.007..0.009 rows=1 loops=13276368)
                           Index Cond: (("CurrentAusClimate"."ClimateId" =
"outer"."ClimateId") AND ("outer"."AusPosNumber" =
"CurrentAusClimate"."AusPosNum") AND ("CurrentAusClimate"."iMonth" =
"outer"."iMonth"))
 Total runtime: 462218.120 ms
(23 rows)






On Thu, 21 Apr 2005, Russell Smith wrote:

> On Thu, 21 Apr 2005 10:44 pm, Shoaib Burq (VPAC) wrote:
> >   ->  Nested Loop  (cost=2.19..1069345.29 rows=16 width=58) (actual time=135.390..366902.373 rows=13276368 loops=1)
> >                      ->  Nested Loop  (cost=2.19..1067304.07 rows=44 width=68) (actual time=107.627..186390.137
rows=13276368loops=1) 
> >                            ->  Nested Loop  (cost=2.19..1067038.94 rows=44 width=52) (actual time=87.255..49743.796
rows=13276368loops=1) 
>
> OUCH, OUCH, OUCH.
>
> Most if not all of the time is going on nested loop joins.  The tuple estimates are off by a factore of 10^6 which is
meansit's chosing the wrong 
> join type.
>
> you could set enable_seqscan to OFF;  to test what he performance is like with a different plan, and then set it back
on.
>
> However you really need to get the row count estimates up to something comparable.  within a factor of 10 at least.
> A number of the other rows estimates seem to be off by a reasonable amount too.  You may want to bump up the
statisticson the relevant 
> columns.  I can't find what they are from looking at that, I probably should be able too, but it's late.
>
> If you get the stats up to something near the real values, then the planner will choose a different plan, which
shouldgive a huge performance 
> increase.
>
> Regards
>
> Russell Smith.
>
>

--
Shoaib Burq
--
VPAC - Geospatial Applications Developer
Building 91, 110 Victoria Street,
Carlton South, Vic 3053, Australia
_______________________________________________________________
w: www.vpac.org  | e: sab_AT_vpac_DOT_org | mob: +61.431-850039




Re: two queries and dual cpu (perplexed)

From
John A Meinel
Date:
Shoaib Burq (VPAC) wrote:

>Just tried it with the following changes:
>
>shared_buffers = 10600
>work_mem = 102400
>enable_seqscan = false
>
>still no improvement
>
>Ok here's the Plan with the enable_seqscan = false:
>ausclimate=# explain ANALYZE  select count(*) from "getfutureausclimate";
>
>
Actually, you probably don't want enable_seqscan=off, you should try:
SET enable_nestloop TO off.
The problem is that it is estimating there will only be 44 rows, but in
reality there are 13M rows. It almost definitely should be doing a
seqscan with a sort and merge join.

Also, please attach you explain analyzes, the wrapping is really hard to
read.

I don't understand how postgres could get the number of rows that wrong.

It seems to be misestimating the number of entries in IX_ClimateId

Here:

->  Index Scan using "PK_Aus40_DEM" on "Aus40_DEM"  (cost=0.00..6.01 rows=1 width=16) (actual time=0.005..0.006 rows=1
loops=13276368)
    Index Cond: ("outer"."AusPosNumber" = "Aus40_DEM"."AusPosNumber")
->  Index Scan using "PK_CurrentAusClimate" on "CurrentAusClimate"  (cost=0.00..46.20 rows=11 width=14) (actual
time=0.007..0.009rows=1 loops=13276368) 

The first index scan is costing you 0.006*13276368=79s, and the second one is 119s.

I can't figure out exactly what is where from the formatting, but the query that seems misestimated is:
->  Index Scan using "IX_ClimateId" on "ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20) (actual
time=28.311..17212.703rows=13276368 loops=1) 
    Index Cond: ("outer"."ClimateId" = "ClimateChangeModel40"."ClimateId")

Is there an unexpected correlaction between
ClimateChangeModel40"."ClimateId" and whatever "outer" is at this point?

John
=:->


Attachment

Re: two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
Please see attached the output from explain analyse. This is with the

    shared_buffers = 10600
    work_mem = 102400
    enable_seqscan = true

BTW I guess should mention that I am doing the select count(*) on a View.

Ran the Explain analyse with the nestedloop disabled but it was taking
forever... and killed it after 30mins.

Thanks
shoaib
On Thu, 21 Apr 2005, John A Meinel wrote:

> Shoaib Burq (VPAC) wrote:
>
> >Just tried it with the following changes:
> >
> >shared_buffers = 10600
> >work_mem = 102400
> >enable_seqscan = false
> >
> >still no improvement
> >
> >Ok here's the Plan with the enable_seqscan = false:
> >ausclimate=# explain ANALYZE  select count(*) from "getfutureausclimate";
> >
> >
> Actually, you probably don't want enable_seqscan=off, you should try:
> SET enable_nestloop TO off.
> The problem is that it is estimating there will only be 44 rows, but in
> reality there are 13M rows. It almost definitely should be doing a
> seqscan with a sort and merge join.
>
> Also, please attach you explain analyzes, the wrapping is really hard to
> read.
>
> I don't understand how postgres could get the number of rows that wrong.
>
> It seems to be misestimating the number of entries in IX_ClimateId
>
> Here:
>
> ->  Index Scan using "PK_Aus40_DEM" on "Aus40_DEM"  (cost=0.00..6.01 rows=1 width=16) (actual time=0.005..0.006
rows=1loops=13276368) 
>     Index Cond: ("outer"."AusPosNumber" = "Aus40_DEM"."AusPosNumber")
> ->  Index Scan using "PK_CurrentAusClimate" on "CurrentAusClimate"  (cost=0.00..46.20 rows=11 width=14) (actual
time=0.007..0.009rows=1 loops=13276368) 
>
> The first index scan is costing you 0.006*13276368=79s, and the second one is 119s.
>
> I can't figure out exactly what is where from the formatting, but the query that seems misestimated is:
> ->  Index Scan using "IX_ClimateId" on "ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20) (actual
time=28.311..17212.703rows=13276368 loops=1) 
>     Index Cond: ("outer"."ClimateId" = "ClimateChangeModel40"."ClimateId")
>
> Is there an unexpected correlaction between
> ClimateChangeModel40"."ClimateId" and whatever "outer" is at this point?
>
> John
> =:->
>
>


Attachment

Re: two queries and dual cpu (perplexed)

From
Gavin Sherry
Date:
On Fri, 22 Apr 2005, Shoaib Burq (VPAC) wrote:

> Please see attached the output from explain analyse. This is with the
>
>     shared_buffers = 10600
>     work_mem = 102400
>     enable_seqscan = true
>
> BTW I guess should mention that I am doing the select count(*) on a View.
>
> Ran the Explain analyse with the nestedloop disabled but it was taking
> forever... and killed it after 30mins.

Try increasing stats collection on ClimateChangeModel40.ClimateId:

alter table ClimateChangeModel40 alter column ClimateId set statistics 1000;
analyze ClimateChangeModel40;

Gavin

Re: two queries and dual cpu (perplexed)

From
Jeff
Date:
On Apr 21, 2005, at 11:33 PM, Shoaib Burq (VPAC) wrote:

>
> BTW I guess should mention that I am doing the select count(*) on a
> View.
>

A bit of a silly question...
but are you actually selecting all the rows from this query in
production or would it be more selective?  ie select * from bigslowview
where bah = 'snort'?


> Ran the Explain analyse with the nestedloop disabled but it was taking
> forever... and killed it after 30mins.
>

If it takes too long you can run just plain explain (no analyze) and it
will show you the plan.  This is nearly always instant... it'll give
you a clue as to if your setting changes did anything.

You may need to end up breaking some parts of this up into subqueries.
I've had to do this before.  I had one query that just ran too dang
slow as a join so I modified it into a subquery type deal.  Worked
great.  However since you are selecting ALL rows I doubt that will help
much.

Another option may be to use materialized views.  Not sure how
"dynamic" your data model is. It could help.

--
Jeff Trout <jeff@jefftrout.com>
http://www.jefftrout.com/
http://www.stuarthamm.net/


Re: two queries and dual cpu (perplexed)

From
Daniel Schuchardt
Date:
Shoaib Burq (VPAC) schrieb:

>Hi everybody,
>
>One of our clients was using SQL-Server and decided to switch to
>PostgreSQL 8.0.1.
>
>Hardware: Dual processor  Intel(R) Xeon(TM) CPU 3.40GHz
>OS: Enterprise Linux with 2.6.9-5 SMP kernel
>Filesystem: ext3
>SHMMAX: $ cat  /proc/sys/kernel/shmmax
>6442450944 <--- beleive that's ~6.5 GB, total ram is 8GB
>Database: 15GB in size with a few tables with over 80 million rows.
>
>Here is a snippit from the output of
>SELECT oid , relname, relpages, reltuples
>        FROM pg_class ORDER BY relpages DESC;
>    oid    |             relname             | relpages |  reltuples
>-----------+---------------------------------+----------+-------------
>     16996 | CurrentAusClimate               |   474551 | 8.06736e+07
>     16983 | ClimateChangeModel40            |   338252 | 5.31055e+07
> 157821816 | PK_CurrentAusClimate            |   265628 | 8.06736e+07
> 157835995 | idx_climateid                   |   176645 | 8.06736e+07
> 157835996 | idx_ausposnum                   |   176645 | 8.06736e+07
> 157835997 | idx_climatevalue              |   176645 | 8.06736e+07
> 157821808 | PK_ClimateModelChange_40        |   174858 | 5.31055e+07
> 157821788 | IX_iMonth001                    |   116280 | 5.31055e+07
> 157821787 | IX_ClimateId                    |   116280 | 5.31055e+07
> 157821786 | IX_AusPosNumber                 |   116280 | 5.31055e+07
>     17034 | NeighbourhoodTable              |    54312 | 1.00476e+07
> 157821854 | PK_NeighbourhoodTable           |    27552 | 1.00476e+07
> 157821801 | IX_NeighbourhoodId              |    22002 | 1.00476e+07
> 157821800 | IX_NAusPosNumber                |    22002 | 1.00476e+07
> 157821799 | IX_AusPosNumber006              |    22002 | 1.00476e+07
>[...]
>
>To test the performance of the database we ran one of the most demanding
>queries that exist with the following embarrassing results:
>
>Query Execution time on:
>SQL-Server (dual processor xeon)  3min 11sec
>PostgreSQL (SMP IBM Linux server) 5min 30sec
>
>Now I have not touch the $PGDATA/postgresql.conf (As I know very little
>about memory tuning) Have run VACCUM & ANALYZE.
>
>The client understands that they may not match the performance for a
>single query as there is no multithreading. So they asked me to
>demonstrate the benefits of Postgresql's multiprocessing capabilities.
>
>To do that I modified the most demanding query to create a second query
>and ran them in parallel:
>
>$ time ./run_test1.sh
>$ cat ./run_test1.sh
>/usr/bin/time -p psql -f ./q1.sql ausclimate > q1.out 2>q1.time &
>/usr/bin/time -p psql -f ./q2.sql ausclimate > q2.out 2>q2.time
>
>and the time taken is *twice* that for the original. The modification was
>minor. The queries do make use of both CPUs:
>
> 2388 postgres 16 0 79640 15m 11m R 80.9 0.2 5:05.81 postmaster
> 2389 postgres 16 0 79640 15m 11m R 66.2 0.2 5:04.25 postmaster
>
>But I can't understand why there's no performance improvement and infact
>there seems to be no benefit of multiprocessing.  Any ideas? I don't know
>enough about the locking procedures employed by postgres but one would
>think this shouldn't be and issue with read-only queries.
>
>Please don't hesitate to ask me for more info like, the query or the
>output of explain, or stats on memory usage. I just wanted to keep this
>short and provide more info as the cogs start turning :-)
>
>Thanks & Regards
>Shoaib
>
>
>
>---------------------------(end of broadcast)---------------------------
>TIP 2: you can get off all lists at once with the unregister command
>    (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
>
>
>
I think you should post the SQL-Statement and EXPLAIN ANALYSE - Output
here to get a usefull awnser.
(EXPLAIN ANALYSE SELECT * FROM x WHERE ---)

Daniel

Re: two queries and dual cpu (perplexed)

From
Kenneth Marshall
Date:
On Thu, Apr 21, 2005 at 08:24:15AM -0400, Jeff wrote:
>
> On Apr 21, 2005, at 7:49 AM, Shoaib Burq (VPAC) wrote:
>
> >Now I have not touch the $PGDATA/postgresql.conf (As I know very little
> >about memory tuning) Have run VACCUM & ANALYZE.
> >
> You should really, really bump up shared_buffers and given you have 8GB
> of ram this query would likely benefit from more work_mem.
>
> >and the time taken is *twice* that for the original. The modification
> >was
> >minor. The queries do make use of both CPUs:
> >
> Is this an IO intensive query?  If running both in parellel results in
> 2x the run time and you have sufficient cpus it would (to me) indicate
> you don't have enough IO bandwidth to satisfy the query.
>

I would add to Jeff's comments, that the default configuration parameters
are fairly-to-very conservative which tends to produce plans with more I/O.
Bumping your shared_buffers, work_mem, and effective_cache_size should
allow the planner to favor plans that utilize more memory but require
less I/O. Also, with small amounts of work_mem, hash joins cannot be
used and the planner will resort to nested loops.

Ken

Re: two queries and dual cpu (perplexed)

From
Tom Lane
Date:
John A Meinel <john@arbash-meinel.com> writes:
> Actually, you probably don't want enable_seqscan=off, you should try:
> SET enable_nestloop TO off.
> The problem is that it is estimating there will only be 44 rows, but in
> reality there are 13M rows. It almost definitely should be doing a
> seqscan with a sort and merge join.

Not nestloops anyway.

> I don't understand how postgres could get the number of rows that wrong.

No stats, or out-of-date stats is the most likely bet.

> I can't figure out exactly what is where from the formatting, but the query that seems misestimated is:
> ->  Index Scan using "IX_ClimateId" on "ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20) (actual
time=28.311..17212.703rows=13276368 loops=1) 
>     Index Cond: ("outer"."ClimateId" = "ClimateChangeModel40"."ClimateId")

Yeah, that's what jumped out at me too.  It's not the full explanation
for the join number being so far off, but this one at least you have a
chance to fix by updating the stats on ClimateChangeModel40.

            regards, tom lane

Re: two queries and dual cpu (perplexed)

From
"Shoaib Burq (VPAC)"
Date:
OK ... so just to clearify...  (and pardon my ignorance):

I need to increase the value of 'default_statistics_target' variable and
then run VACUUM ANALYZE, right? If so what should I choose for the
'default_statistics_target'?

BTW I only don't do any sub-selection on the View.

I have attached the view in question and the output of:
SELECT oid , relname, relpages, reltuples
        FROM pg_class ORDER BY relpages DESC;

reg
shoaib

On Sat, 23 Apr 2005, Tom Lane wrote:

> John A Meinel <john@arbash-meinel.com> writes:
> > Actually, you probably don't want enable_seqscan=off, you should try:
> > SET enable_nestloop TO off.
> > The problem is that it is estimating there will only be 44 rows, but in
> > reality there are 13M rows. It almost definitely should be doing a
> > seqscan with a sort and merge join.
>
> Not nestloops anyway.
>
> > I don't understand how postgres could get the number of rows that wrong.
>
> No stats, or out-of-date stats is the most likely bet.
>
> > I can't figure out exactly what is where from the formatting, but the query that seems misestimated is:
> > ->  Index Scan using "IX_ClimateId" on "ClimateChangeModel40"  (cost=0.00..1063711.75 rows=265528 width=20) (actual
time=28.311..17212.703rows=13276368 loops=1) 
> >     Index Cond: ("outer"."ClimateId" = "ClimateChangeModel40"."ClimateId")
>
> Yeah, that's what jumped out at me too.  It's not the full explanation
> for the join number being so far off, but this one at least you have a
> chance to fix by updating the stats on ClimateChangeModel40.
>
>             regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: you can get off all lists at once with the unregister command
>     (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
>

--
Shoaib Burq
--
VPAC - Geospatial Applications Developer
Building 91, 110 Victoria Street,
Carlton South, Vic 3053, Australia
_______________________________________________________________
w: www.vpac.org  | e: sab_AT_vpac_DOT_org | mob: +61.431-850039



Attachment

Re: two queries and dual cpu (perplexed)

From
"Dave Held"
Date:
> -----Original Message-----
> From: Shoaib Burq (VPAC) [mailto:sab@vpac.org]
> Sent: Tuesday, April 26, 2005 9:31 AM
> To: Tom Lane
> Cc: John A Meinel; Russell Smith; Jeff;
> pgsql-performance@postgresql.org
> Subject: Re: [PERFORM] two queries and dual cpu (perplexed)
>
>
> OK ... so just to clearify...  (and pardon my ignorance):
>
> I need to increase the value of 'default_statistics_target'
> variable and then run VACUUM ANALYZE, right?

Not necessarily.  You can set the statistics for a single
column with ALTER TABLE.

> If so what should I choose for the 'default_statistics_target'?
> [...]

Since you have a decently large table, go for the max setting
which is 1000.

__
David B. Held
Software Engineer/Array Services Group
200 14th Ave. East,  Sartell, MN 56377
320.534.3637 320.253.7800 800.752.8129

Re: two queries and dual cpu (perplexed)

From
John A Meinel
Date:
Shoaib Burq (VPAC) wrote:
> OK ... so just to clearify...  (and pardon my ignorance):
>
> I need to increase the value of 'default_statistics_target' variable and
> then run VACUUM ANALYZE, right? If so what should I choose for the
> 'default_statistics_target'?
>
> BTW I only don't do any sub-selection on the View.
>
> I have attached the view in question and the output of:
> SELECT oid , relname, relpages, reltuples
>         FROM pg_class ORDER BY relpages DESC;
>
> reg
> shoaib

Actually, you only need to alter the statistics for that particular
column, not for all columns in the db.

What you want to do is:

ALTER TABLE "ClimateChangeModel40"
    ALTER COLUMN <whatever the column is>
    SET STATISTICS 100;
VACUUM ANALYZE "ClimateChangeModel40";

The column is just the column that you have the "IX_ClimateId" index on,
I don't know which one that is.

The statistics value ranges from 1 - 1000, the default being 10, and for
indexed columns you are likely to want somewhere between 100-200.

If you set it to 100 and the planner is still mis-estimating the number
of rows, try 200, etc.

The reason to keep the number low is because with a high number the
planner has to spend more time planning. But especially for queries like
this one, you'd rather the query planner spent a little bit more time
planning, and got the right plan.

John
=:->


Attachment