Re: 9.2beta1, parallel queries, ReleasePredicateLocks, CheckForSerializableConflictIn in the oprofile

On Wed, May 30, 2012 at 12:11 PM, Robert Haas <robertmhaas@gmail.com> wrote:
> On Wed, May 30, 2012 at 12:58 PM, Sergey Koposov <koposov@ast.cam.ac.uk> wrote:
>> Here is the one to one comparison of the 'bogged' **********
>>
>>  QUERY PLAN
>>
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
>>  Sort  (cost=63835201.73..63835214.23 rows=5000 width=498) (actual
>> time=18007.500..18007.500 rows=0 loops=1)
>>   Sort Key: y.x
>>   Sort Method: quicksort  Memory: 25kB
>>   ->  Subquery Scan on y  (cost=0.00..63834894.54 rows=5000 width=498)
>> (actual time=18007.454..18007.454 rows=0 loops=1)
>>         Filter: ((y.x % 16::bigint) = 7)
>>         Rows Removed by Filter: 1000000
>>         ->  Limit  (cost=0.00..63819894.51 rows=1000002 width=490) (actual
>> time=0.047..17734.570 rows=1000000 loops=1)
>>               ->  Seq Scan on idt_photoobservation_small o
>>  (cost=0.00..63819894.51 rows=1000002 width=490) (actual
>> time=0.045..17543.902 rows=1000000 loops=1)
>>                     SubPlan 1
>>                       ->  Index Scan using idt_match_transitid_idx on
>> idt_match m  (cost=0.00..63.74 rows=1 width=8) (actual time=0.015..0.015
>> rows=1 loops=1000000)
>>
>>                             Index Cond: (transitid = o.transitid)
>>  Total runtime: 18056.866 ms
>> (12 rows)
>>
>> Time: 18067.929 ms
>> *************************
>>
>> vs  non-bogged:
>>
>> **************************
>>
>>  QUERY PLAN
>>
----------------------------------------------------------------------------------------------------------------------------------------------------------------------
>>  Sort  (cost=63835201.73..63835214.23 rows=5000 width=498) (actual
>> time=6635.133..6635.133 rows=0 loops=1)
>>   Sort Key: y.x
>>   Sort Method: quicksort  Memory: 25kB
>>   ->  Subquery Scan on y  (cost=0.00..63834894.54 rows=5000 width=498)
>> (actual time=6635.091..6635.091 rows=0 loops=1)
>>         Filter: ((y.x % 16::bigint) = 7)
>>         Rows Removed by Filter: 1000000
>>         ->  Limit  (cost=0.00..63819894.51 rows=1000002 width=490) (actual
>> time=0.059..6344.683 rows=1000000 loops=1)
>>               ->  Seq Scan on idt_photoobservation_small o
>>  (cost=0.00..63819894.51 rows=1000002 width=490) (actual
>> time=0.056..6149.429 rows=1000000 loops=1)
>>
>>                     SubPlan 1
>>                       ->  Index Scan using idt_match_transitid_idx on
>> idt_match m  (cost=0.00..63.74 rows=1 width=8) (actual time=0.003..0.004
>> rows=1 loops=1000000)
>>                             Index Cond: (transitid = o.transitid)
>>  Total runtime: 6669.215 ms
>> (12 rows)
>>
>> Time: 6673.991 ms
>
> Hmm.  So the total time across all loops is 3000-4000 ms in the
> unbogged case, and 15000 ms in the bogged case.  The time for the
> seqscan parent is 6344.683 in the unbogged case, so ~3s once you
> subtract out the index scans, and 17543.902 in the bogged case, so ~3s
> once you subtract out the index scans.  So this seems to support
> Merlin's theory that the index scan is what's getting slow under heavy
> concurrency.  Apparently, the index scan slows down 4-5x but the
> seqscan is just as fast as ever.  Very interesting...

Yeah, an 'index only scan' *would* fix the performance problem if my
theory is correct.  By skipping the heap lookup it would also skip the
buffer retagging which is binding up the multiple concurrent scans.
Sergey, just in case you don't know, an IOS works like this.  If all
the fields that are fetched from a table are present in the index and
the index points towards a tuple on a page that contains only visible
tuples according to the visibility map, you get to skip jumping back
into the heap for visibility checks.  In your case, I think that would
result in almost linear scaling.

Hm, why aren't we getting a IOS?  Just for kicks (assuming this is
test data), can we drop the index on just transitid, leaving the index
on transitid, healpixid?    Is enable_indexonlyscan on?  Has idt_match
been vacuumed?  What kind of plan do you get when do:

select healpixid from idt_match where transitid = <some valid transitid>;

merlin