Re: Performance regression from 8.3.7 to 9.0.3

Nothing?

No ideas?

Did I forget to include some useful bit?

On Fri, Mar 4, 2011 at 8:22 PM, Claudio Freire <klaussfreire(at)gmail(dot)com> wrote:
> Hello, first post to this list.
>
> I have this query that ran in milliseconds in postgres 8.3.7 (usually 50,
> 100ms), and now it takes a full 10 minutes to complete.
>
> I tracked the problem to the usage of hash aggregates to resolve EXISTS
> clauses in conjunction with large IN clauses, which seem to reverse the
> execution plan - in 8.3.7, it would use indices to fetch the rows from the
> IN, then compute the exists with a nested loop, never doing big sequential
> scans. In 9.0.3, it computes the set of applicable entries with a hash
> aggregate, but in order to do that it performs a huge index scan - no
> sequential scans either, but the big index scan is worse.
>
> 9.0.3 always misses the estimate of how many rows will come out the hash
> aggregate, always estimating 200, while in fact the real count is more like
> 300.000. I've tried increasing statistics in all the columns involved, up to
> 4000 for each, to the point where it accurately estimates the input to the
> hash agg, but the output is always estimated to be 200 rows.
>
> Rewriting the query to use 0 < (select count(*)..) instead of EXISTS (select
> * ..) does revert to the old postgres 8.3 plan, although intuitively I would
> think it to be sub-optimal.
>
> The tables in question receive many updates, but never in such a volume as
> to create enough bloat - plus, the tests I've been running are on a
> pre-production server without much traffic (so not many updates - probably
> none in weeks).
>
> The server is a Core 2 E7400 dual core with 4GB of ram running linux and a
> pg 9.0.3 / 8.3.7 (both there, doing migration testing) built from source.
> Quite smaller than our production server, but I've tested the issue on
> higher-end hardware and it produces the same results.
>
> Any ideas as to how to work around this issue?
>
> I can't plug the select count() version everywhere, since I won't be using
> this form of the query every time (it's generated programatically with an
> ORM), and some forms of it perform incredibly worse with the select count().
>
> Also, any help I can provide to fix it upstream I'll be glad to - I believe
> (I would have to check) I can even create a dump of the tables (stripping
> sensitive info of course) - only, well, you'll see the size below - a tad
> big to be mailing it ;-)
>
> pg 9.0 is configured with:
>
> work_mem = 64M
> shared_buffers = 512M
> temp_buffers = 64M
> effective_cache_size = 128M
>
> pg 8.3.7 is configured with:
>
> work_mem = 64M
> shared_buffers = 100M
> temp_buffers = 64M
> effective_cache_size = 128M
>
>
> The query in question:
>
>> SELECT member_statistics.member_id
>>         FROM member_statistics
>>         WHERE member_statistics.member_id IN ( <<400 ids>> ) AND (EXISTS
>> (SELECT mat1.tag_id
>>         FROM member_all_tags_v AS mat1
>>         WHERE mat1.member_id = member_statistics.member_id AND mat1.tag_id
>> IN (640, 641, 3637, 3638, 637, 638, 639) AND mat1.polarity >= 90))
>>
>> -- View: member_all_tags_v
>>
>> CREATE OR REPLACE VIEW member_all_tags_v AS
>>          SELECT member_tags.member_id, member_tags.last_modification_date,
>> member_tags.polarity, member_tags.tag_id, 'mr' AS source
>>            FROM member_tags
>> UNION ALL
>>          SELECT member_profile_tags.member_id,
>> member_profile_tags.last_modification_date, member_profile_tags.polarity,
>> member_profile_tags.tag_id, 'profile' AS source
>>            FROM member_profile_tags;
>>
>> -- Table: member_profile_tags
>>
>> -- DROP TABLE member_profile_tags;
>>
>> CREATE TABLE member_profile_tags
>> (
>>   member_id integer NOT NULL,
>>   last_modification_date timestamp without time zone NOT NULL,
>>   polarity smallint NOT NULL,
>>   tag_id integer NOT NULL,
>>   CONSTRAINT member_profile_tags_pkey PRIMARY KEY (member_id, tag_id),
>>   CONSTRAINT fka52b6e7491ac9123 FOREIGN KEY (tag_id)
>>       REFERENCES tags (id) MATCH SIMPLE
>>       ON UPDATE NO ACTION ON DELETE NO ACTION
>> )
>> WITH (
>>   OIDS=FALSE
>> );
>>
>> -- Index: idx_member_profile_tags_tag_id
>> CREATE INDEX idx_member_profile_tags_tag_id
>>   ON member_profile_tags
>>   USING btree
>>   (tag_id);
>>
>>
>> -- Table: member_tags
>>
>> -- DROP TABLE member_tags;
>> CREATE TABLE member_tags
>> (
>>   member_id integer NOT NULL,
>>   last_modification_date timestamp without time zone NOT NULL,
>>   polarity smallint NOT NULL,
>>   tag_id integer NOT NULL,
>>   CONSTRAINT member_tags_pkey PRIMARY KEY (member_id, tag_id),
>>   CONSTRAINT fk527ef29e91ac9123 FOREIGN KEY (tag_id)
>>       REFERENCES tags (id) MATCH SIMPLE
>>       ON UPDATE NO ACTION ON DELETE NO ACTION
>> )
>> WITH (
>>   OIDS=FALSE
>> );
>>
>> -- Index: idx_member_tags_tag_id
>> CREATE INDEX idx_member_tags_tag_id
>>   ON member_tags
>>   USING btree
>>   (tag_id);
>
>
> member_tags : 637M bytes, 12.7M rows
> member_profile_tags : 1824M bytes, 36.6M rows
> member_statistics : 581M bytes, 2.5M rows
>
> member_profile_tags_pkey : 785M
> member_tags_pkey : 274M
> member_statistics_pkey : 54M
>
> idx_member_tags_tag_id : 274M
> idx_member_profile_tags_tag_id : 785M
>
> member_tags.member_id : 1.217.000 distinct values, mostly evenly spread
> member_profile_tags.member_id : 947.000 distinct values, mostly evenly
> spread
> member_tags.tag_id : 1176 distinct values, some bias towards some values,
> but mostly well spread
> member_profile_tags.tag_id : 1822 distinct values, some bias towards some
> values, but mostly well spread
>
>
> Execution plan for postgresql 8.3.7 - with EXISTS :
> (second run, so it's hitting the disk cache)
>
>>  Bitmap Heap Scan on member_statistics  (cost=2438.19..26177.46 rows=200
>> width=4) (actual time=2.442..15.515 rows=256 loops=1)
>>    Recheck Cond: (member_id = ANY ('{<400 ids>}'::integer[]))
>>    Filter: (subplan)
>>    ->  Bitmap Index Scan on member_statistics_pkey  (cost=0.00..2438.14
>> rows=401 width=0) (actual time=2.105..2.105 rows=342 loops=1)
>>          Index Cond: (member_id = ANY ('{<400 ids>}'::integer[]))
>>    SubPlan
>>      ->  Subquery Scan mat1  (cost=45.50..280.61 rows=31 width=4) (actual
>> time=0.036..0.036 rows=1 loops=341)
>>            ->  Append  (cost=45.50..280.30 rows=31 width=18) (actual
>> time=0.036..0.036 rows=1 loops=341)
>>                  ->  Subquery Scan "*SELECT* 1"  (cost=45.50..63.50 rows=3
>> width=18) (actual time=0.021..0.021 rows=0 loops=341)
>>                        ->  Bitmap Heap Scan on member_tags
>> (cost=45.50..63.47 rows=3 width=18) (actual time=0.020..0.020 rows=0
>> loops=341)
>>                              Recheck Cond: ((member_id = $0) AND (tag_id =
>> ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                              Filter: (polarity >= 90)
>>                              ->  Bitmap Index Scan on member_tags_pkey
>> (cost=0.00..45.50 rows=3 width=0) (actual time=0.018..0.018 rows=0
>> loops=341)
>>                                    Index Cond: ((member_id = $0) AND
>> (tag_id = ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                  ->  Subquery Scan "*SELECT* 2"  (cost=49.48..216.81
>> rows=28 width=18) (actual time=0.025..0.025 rows=1 loops=192)
>>                        ->  Bitmap Heap Scan on member_profile_tags
>> (cost=49.48..216.53 rows=28 width=18) (actual time=0.024..0.024 rows=1
>> loops=192)
>>                              Recheck Cond: ((member_id = $0) AND (tag_id =
>> ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                              Filter: (polarity >= 90)
>>                              ->  Bitmap Index Scan on
>> member_profile_tags_pkey  (cost=0.00..49.47 rows=28 width=0) (actual
>> time=0.023..0.023 rows=1 loops=192)
>>                                    Index Cond: ((member_id = $0) AND
>> (tag_id = ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>
>
> Execution plan for postgresql 8.3.7 - with count() :
> (second run, so it's hitting the disk cache)
>
>>  Bitmap Heap Scan on member_statistics  (cost=2438.18..117455.15 rows=134
>> width=4) (actual time=1.478..16.256 rows=256 loops=1)
>>    Recheck Cond: (member_id = ANY ('{<400 ids>}'::integer[]))
>>    Filter: (0 < (subplan))
>>    ->  Bitmap Index Scan on member_statistics_pkey  (cost=0.00..2438.14
>> rows=401 width=0) (actual time=1.208..1.208 rows=342 loops=1)
>>          Index Cond: (member_id = ANY ('{<400 ids>}'::integer[]))
>>    SubPlan
>>      ->  Aggregate  (cost=280.69..280.70 rows=1 width=4) (actual
>> time=0.042..0.042 rows=1 loops=341)
>>            ->  Append  (cost=45.50..280.30 rows=31 width=18) (actual
>> time=0.029..0.041 rows=1 loops=341)
>>                  ->  Subquery Scan "*SELECT* 1"  (cost=45.50..63.50 rows=3
>> width=18) (actual time=0.017..0.018 rows=0 loops=341)
>>                        ->  Bitmap Heap Scan on member_tags
>> (cost=45.50..63.47 rows=3 width=18) (actual time=0.016..0.016 rows=0
>> loops=341)
>>                              Recheck Cond: ((member_id = $0) AND (tag_id =
>> ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                              Filter: (polarity >= 90)
>>                              ->  Bitmap Index Scan on member_tags_pkey
>> (cost=0.00..45.50 rows=3 width=0) (actual time=0.015..0.015 rows=0
>> loops=341)
>>                                    Index Cond: ((member_id = $0) AND
>> (tag_id = ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                  ->  Subquery Scan "*SELECT* 2"  (cost=49.48..216.81
>> rows=28 width=18) (actual time=0.023..0.023 rows=1 loops=341)
>>                        ->  Bitmap Heap Scan on member_profile_tags
>> (cost=49.48..216.53 rows=28 width=18) (actual time=0.021..0.021 rows=1
>> loops=341)
>>                              Recheck Cond: ((member_id = $0) AND (tag_id =
>> ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                              Filter: (polarity >= 90)
>>                              ->  Bitmap Index Scan on
>> member_profile_tags_pkey  (cost=0.00..49.47 rows=28 width=0) (actual
>> time=0.020..0.020 rows=1 loops=341)
>>                                    Index Cond: ((member_id = $0) AND
>> (tag_id = ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>
> So count or exists it's the same.
>
>
> Execution plan for postgresql 9.0.3 - with count() :
> (second run, so it hits the disk cache)
>
>
>>
>>  Bitmap Heap Scan on member_statistics  (cost=1664.07..32728.36 rows=134
>> width=4) (actual time=1.931..32.529 rows=292 loops=1)
>>    Recheck Cond: (member_id = ANY ('{<400 ids>}'::integer[]))
>>    Filter: (0 < (SubPlan 1))
>>    ->  Bitmap Index Scan on member_statistics_pkey  (cost=0.00..1664.03
>> rows=401 width=0) (actual time=1.555..1.555 rows=401 loops=1)
>>          Index Cond: (member_id = ANY
>> ('{159854,159854,32002710,146073,47034441,170998431,126544544,106848929,51215963,168108711,187048,158374569,148139,44044975,154860208,47770056,47823538,74250935,193208,128981,165102267,169419454,171518656,160916161,176834,182057667,137687748,160390262,570059,129741,129744,163637969,161163988,153832149,130312,192527065,127707,154557148,117472,160652001,127009507,170990308,50784999,193598184,183378665,140992296,52810482,151150,167910137,75057914,169769724,137658154,155280126,169863637,177933057,129653508,170738438,156801,108385032,181001,703242,177927538,145672301,142097,169247875,79110932,187384604,145810205,202885,170990369,158835492,158487527,36492073,178043690,40500011,205618,118250288,178021169,180091698,166707,166350922,150842169,184523578,46750524,43276426,164671,138048,166390593,129525899,169495369,160751415,125332301,113503054,183145296,99724114,121683,182793045,178037590,193551192,178295641,184224603,82117469,52878175,135213920,201570,177871715,159755,178455356,44462011,126577519,154833776,129670001,129906,188563,154484,197493,173958,47784176,53940031,149611388,136064,183827330,166173573,163649,169399788,205706,138124,8375182,160587235,194335635,129084308,144277,59081622,113560,183195,129508252,170139,197541,161352615,154537,183014316,191974318,125635503,183845810,78334900,170116007,165262264,148935615,32534347,126806981,172936135,170150857,148427,153832398,101419987,187423701,44440534,139316185,211930,182936539,127546338,43897827,132069,153447398,178228199,40762344,119785,46990314,128082923,207853,193338353,197618,51626995,154063860,177007606,176865,202860,154407934,158417322,154296832,161092610,178080772,177953797,187513176,169404588,160724823,177941517,137352910,176510987,197650,522414,148502,169894745,181746180,48571418,183717039,181276,197661,123935,178088992,187612193,192752674,183469095,199721,47033387,125592620,192588845,177929264,58709043,192717878,49531959,178913,207370,179381,195648,192724034,192545291,149363781,184595528,148689993,144460,177947725,183736845,178007419,164948,160008482,159790607,160191580,156787805,170974303,145243232,154351120,158820,119910,52757612,182338672,121970,186621,203893,160724086,156334768,158469653,117889,183762051,138774,156614507,195726,43654288,177921170,178128022,197783,169487513,197786,187298671,188828828,183865413,165201056,192561636,168168615,126151,124189868,115886,178216111,182873264,192599219,156800180,135009461,192641032,192529268,184554685,136060779,178005185,148389058,164043,32523462,185543,180718799,155403472,166180387,156478676,164314325,8379920,187299031,140504,173273636,193191119,154330335,140087504,56446178,93514979,195812,139384038,152807,187403497,130283,183084268,47942893,44846319,115953,167818483,171025620,158375162,125411199,139319850,181947650,161244419,165209349,51082504,162387211,153805357,183655696,153851154,175314196,137604313,158342426,197917,182856581,171296,204065,113883,182990726,152871,148815145,154998058,180477228,144537138,152879,120112,182039091,156349748,112567,143458553,178107708,45284670,177884725,150820160,125695297,169819463,154498377,189770,124235,47764812,8338658,178265422,125013327,171019601,154787154,236884,47089209,138584,178009433,184524122,132613470,154213727,118112,164918105,126104932,142845158,178056551,177857896,148640999,178046316,126318,151584111,184473832,178205592,184227190,154178935,187748684,125523322,154664315,46991594,154146174,187430273,150857090,154219907,171074949,178077062,160212361,41971083,146929,176596368,183045016,150822290,165059988,163717,178029807,140019102,194117,107615649,193541019,127933340,51142059,189869,153855406,184212914,50566580,172972617,172503347,191762681,165557692}'::integer[]))
>>    SubPlan 1
>>      ->  Aggregate  (cost=73.17..73.18 rows=1 width=4) (actual
>> time=0.070..0.071 rows=1 loops=400)
>>            ->  Append  (cost=31.23..73.15 rows=2 width=18) (actual
>> time=0.047..0.065 rows=1 loops=400)
>>                  ->  Subquery Scan on "*SELECT* 1"  (cost=31.23..35.26
>> rows=1 width=18) (actual time=0.025..0.027 rows=0 loops=400)
>>                        ->  Bitmap Heap Scan on member_tags
>> (cost=31.23..35.25 rows=1 width=18) (actual time=0.022..0.022 rows=0
>> loops=400)
>>                              Recheck Cond: ((member_id = $0) AND (tag_id =
>> ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                              Filter: (polarity >= 90)
>>                              ->  Bitmap Index Scan on member_tags_pkey
>> (cost=0.00..31.23 rows=1 width=0) (actual time=0.018..0.018 rows=0
>> loops=400)
>>                                    Index Cond: ((member_id = $0) AND
>> (tag_id = ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                  ->  Subquery Scan on "*SELECT* 2"  (cost=33.85..37.88
>> rows=1 width=18) (actual time=0.029..0.031 rows=1 loops=400)
>>                        ->  Bitmap Heap Scan on member_profile_tags
>> (cost=33.85..37.87 rows=1 width=18) (actual time=0.025..0.026 rows=1
>> loops=400)
>>                              Recheck Cond: ((member_id = $0) AND (tag_id =
>> ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>>                              Filter: (polarity >= 90)
>>                              ->  Bitmap Index Scan on
>> member_profile_tags_pkey  (cost=0.00..33.85 rows=1 width=0) (actual
>> time=0.022..0.022 rows=1 loops=400)
>>                                    Index Cond: ((member_id = $0) AND
>> (tag_id = ANY ('{640,641,3637,3638,637,638,639}'::integer[])))
>
>
> Execution plan for postgresql 9.0.3 - with EXISTS :
> (second run, so it "would hit" the disk cache - only not because there's not
> enough RAM)
>
>>  Nested Loop  (cost=278457.13..279957.12 rows=200 width=4) (actual
>> time=65631.381..607728.817 rows=292 loops=1)
>>    ->  HashAggregate  (cost=278457.13..278459.13 rows=200 width=4) (actual
>> time=64505.008..65078.142 rows=306596 loops=1)
>>          ->  Append  (cost=807.95..276438.85 rows=161462 width=18) (actual
>> time=562.372..63665.663 rows=345836 loops=1)
>>                ->  Subquery Scan on "*SELECT* 1"  (cost=807.95..71891.14
>> rows=41738 width=18) (actual time=562.368..14646.508 rows=95514 loops=1)
>>                      ->  Bitmap Heap Scan on member_tags
>> (cost=807.95..71473.76 rows=41738 width=18) (actual time=562.364..14402.566
>> rows=95514 loops=1)
>>                            Recheck Cond: (tag_id = ANY
>> ('{640,641,3637,3638,637,638,639}'::integer[]))
>>                            Filter: (polarity >= 90)
>>                            ->  Bitmap Index Scan on
>> idx_member_tags_tag_id  (cost=0.00..797.52 rows=42448 width=0) (actual
>> time=529.863..529.863 rows=95577 loops=1)
>>                                  Index Cond: (tag_id = ANY
>> ('{640,641,3637,3638,637,638,639}'::integer[]))
>>                ->  Subquery Scan on "*SELECT* 2"  (cost=2249.62..204547.71
>> rows=119724 width=18) (actual time=1073.523..48170.919 rows=250322 loops=1)
>>                      ->  Bitmap Heap Scan on member_profile_tags
>> (cost=2249.62..203350.47 rows=119724 width=18) (actual
>> time=1073.520..47529.880 rows=250322 loops=1)
>>                            Recheck Cond: (tag_id = ANY
>> ('{640,641,3637,3638,637,638,639}'::integer[]))
>>                            Filter: (polarity >= 90)
>>                            ->  Bitmap Index Scan on
>> idx_member_profile_tags_tag_id  (cost=0.00..2219.68 rows=119724 width=0)
>> (actual time=963.341..963.341 rows=250322 loops=1)
>>                                  Index Cond: (tag_id = ANY
>> ('{640,641,3637,3638,637,638,639}'::integer[]))
>>    ->  Index Scan using member_statistics_pkey on member_statistics
>> (cost=0.00..7.48 rows=1 width=4) (actual time=1.767..1.767 rows=0
>> loops=306596)
>>          Index Cond: (member_statistics.member_id = "*SELECT*
>> 1".member_id)
>>          Filter: (member_statistics.member_id = ANY ('{<400
>> ids>}'::integer[]))
>>  Total runtime: 607734.942 ms
>
>
>
>
>