Thread: BUG #1851: Performance reduction from 8.0.3

BUG #1851: Performance reduction from 8.0.3

From
"Steve Wormley"
Date:
The following bug has been logged online:

Bug reference:      1851
Logged by:          Steve Wormley
Email address:      steve@wormley.com
PostgreSQL version: 8.1beta1
Operating system:   RedHat Linux, Kernel: 2.6.12.2
Description:        Performance reduction from 8.0.3
Details:

Did a dump and restore of my DB to 8.1beta1 (running concurrently with
8.0.3) and performance on the same query is about 50% slower with the beta.
Ran query twice on each instance in sequence to make sure all data was in OS
cache.

8.0.3
 explain analyze select 7208,avg(data.sl),mcc,mnc from grid_geography_link
as gglink , meta_data as meta, signal_level_stats as data where data.ogc_fid
= meta.ogc_fid AND data.isvalid=true AND meta.isvalid = true AND meta.gridid
= gglink.gridid and 7208 = gglink.geographyid  group by mcc,mnc;

          QUERY PLAN

----------------------------------------------------------------------------
----------------------------------------------------------------------------
--------------------------------
 HashAggregate  (cost=36735.67..36736.24 rows=228 width=16) (actual
time=3834.630..3834.668 rows=8 loops=1)
   ->  Nested Loop  (cost=16.19..36722.89 rows=1704 width=16) (actual
time=141.628..3526.391 rows=67824 loops=1)
         ->  Merge Join  (cost=16.19..30737.86 rows=1766 width=16) (actual
time=141.565..1566.594 rows=68547 loops=1)
               Merge Cond: ("outer".gridid = "inner".gridid)
               ->  Index Scan using meta_data_gridid on meta_data meta
(cost=0.00..35362.89 rows=312214 width=20) (actual time=0.103..499.071
rows=89081 loops=1)
                     Filter: (isvalid = true)
               ->  Sort  (cost=16.19..16.76 rows=229 width=4) (actual
time=7.291..219.951 rows=68567 loops=1)
                     Sort Key: gglink.gridid
                     ->  Index Scan using grid_geography_link_geographyid on
grid_geography_link gglink  (cost=0.00..7.22 rows=229 width=4) (actual
time=0.077..3.865 rows=995 loops=1)
                           Index Cond: (7208 = geographyid)
         ->  Index Scan using signal_level_stats_pkey on signal_level_stats
data  (cost=0.00..3.38 rows=1 width=16) (actual time=0.011..0.015 rows=1
loops=68547)
               Index Cond: (data.ogc_fid = "outer".ogc_fid)
               Filter: (isvalid = true)
 Total runtime: 3834.868 ms
(14 rows)



8.1beta1:
explain analyze select 7208,avg(data.sl),mcc,mnc from grid_geography_link as
gglink , meta_data as meta, signal_level_stats as data where data.ogc_fid =
meta.ogc_fid AND data.isvalid=true AND meta.isvalid = true AND meta.gridid =
gglink.gridid and 7208 = gglink.geographyid  group by mcc,mnc;

      QUERY PLAN

----------------------------------------------------------------------------
----------------------------------------------------------------------------
------------------------
 HashAggregate  (cost=41180.34..41230.34 rows=20000 width=16) (actual
time=8834.251..8834.372 rows=8 loops=1)
   ->  Merge Join  (cost=31059.37..37808.18 rows=449621 width=16) (actual
time=7969.032..8614.804 rows=67823 loops=1)
         Merge Cond: ("outer".gridid = "inner".gridid)
         ->  Sort  (cost=971.33..973.57 rows=896 width=4) (actual
time=7.344..10.284 rows=995 loops=1)
               Sort Key: gglink.gridid
               ->  Bitmap Heap Scan on grid_geography_link gglink
(cost=6.13..927.39 rows=896 width=4) (actual time=0.289..3.687 rows=995
loops=1)
                     Recheck Cond: (7208 = geographyid)
                     ->  Bitmap Index Scan on
grid_geography_link_geographyid  (cost=0.00..6.13 rows=896 width=0) (actual
time=0.260..0.260 rows=995 loops=1)
                           Index Cond: (7208 = geographyid)
         ->  Sort  (cost=30088.04..30338.95 rows=100362 width=20) (actual
time=7864.261..8124.173 rows=88143 loops=1)
               Sort Key: meta.gridid
               ->  Hash Join  (cost=8165.88..21750.54 rows=100362 width=20)
(actual time=2863.617..6363.921 rows=309036 loops=1)
                     Hash Cond: ("outer".ogc_fid = "inner".ogc_fid)
                     ->  Bitmap Heap Scan on meta_data meta
(cost=1166.30..10165.86 rows=204656 width=20) (actual time=61.030..1271.910
rows=314108 loops=1)
                           Filter: isvalid
                           ->  Bitmap Index Scan on meta_data_isvalid
(cost=0.00..1166.30 rows=204656 width=0) (actual time=58.417..58.417
rows=314108 loops=1)
                                 Index Cond: (isvalid = true)
                     ->  Hash  (cost=6497.77..6497.77 rows=200724 width=16)
(actual time=2802.385..2802.385 rows=394772 loops=1)
                           ->  Bitmap Heap Scan on signal_level_stats data
(cost=1144.53..6497.77 rows=200724 width=16) (actual time=71.196..1458.890
rows=394772 loops=1)
                                 Filter: isvalid
                                 ->  Bitmap Index Scan on
signal_level_stats_isvalid  (cost=0.00..1144.53 rows=200724 width=0) (actual
time=69.892..69.892 rows=394772 loops=1)
                                       Index Cond: (isvalid = true)
 Total runtime: 8884.601 ms
(23 rows)



(Of course, I was hoping with the new bitmaps things would be faster.)

Re: BUG #1851: Performance reduction from 8.0.3

From
Tom Lane
Date:
"Steve Wormley" <steve@wormley.com> writes:
> Did a dump and restore of my DB to 8.1beta1 (running concurrently with
> 8.0.3) and performance on the same query is about 50% slower with the beta.
> Ran query twice on each instance in sequence to make sure all data was in OS
> cache.

Did you vacuum analyze (or at least analyze) both databases?  The
rowcount estimates seem quite a bit different, which suggests the
two planners aren't working with the same stats.

            regards, tom lane

Re: BUG #1851: Performance reduction from 8.0.3

From
Steve Wormley
Date:
On 2005-08-26 16:17, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:

> "Steve Wormley" <steve@wormley.com> writes:
>> Did a dump and restore of my DB to 8.1beta1 (running concurrently with
>> 8.0.3) and performance on the same query is about 50% slower with the beta.
>> Ran query twice on each instance in sequence to make sure all data was in OS
>> cache.
>
> Did you vacuum analyze (or at least analyze) both databases?  The
> rowcount estimates seem quite a bit different, which suggests the
> two planners aren't working with the same stats.
>

Sigh, I swore I remembered to at least analyze both, but I guess not. After
vacuum analyze 8.1beta1 is fine and happy and using a virtually identical
plan and coming in a few hundred milliseconds faster.

Thanks,
-Steve Wormley