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

On Wed, May 30, 2012 at 12:58 PM, Sergey Koposov <koposov(at)ast(dot)cam(dot)ac(dot)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...

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company