Обсуждение: GiST, caching, and consistency

От:
Matthew Wakeling
Дата:

I'm seeing an interesting phenomenon while I'm trying to
performance-optimise a GiST index. Basically, running a performance test
appears to be the same thing as running a random number generator. For
example, here I'm running the same statement eight times in quick
succession:

> modmine_overlap_test=# \timing
> Timing is on.
> modmine_overlap_test=# select count(*) from (select * FROM
> locatedsequencefeatureoverlappingfeatures limit 1000000) AS a;
>   count
> ---------
>  1000000
> (1 row)
>
> Time: 138583.140 ms
>
> Time: 153769.152 ms
>
> Time: 127518.574 ms
>
> Time: 49629.036 ms
>
> Time: 70926.034 ms
>
> Time: 7625.034 ms
>
> Time: 7382.609 ms
>
> Time: 7985.379 ms

"locatedsequencefeatureoverlappingfeatures" is a view, which performs a
join with a GiST index. The machine was otherwise idle, and has plenty of
RAM free.

Shouldn't the data be entirely in cache the second time I run the
statement? However, it's worse than that, because while the long-running
statements were running, I saw significant CPU usage in top - more than
eight seconds worth. Again, one one test there was no io-wait, but on a
subsequent test there was lots of io-wait.

How can this be so inconsistent?

Matthew

--
 "Interwoven alignment preambles are not allowed."
 If you have been so devious as to get this message, you will understand
 it, and you deserve no sympathy.  -- Knuth, in the TeXbook

От:
Robert Haas
Дата:

On Tue, Aug 4, 2009 at 12:06 PM, Matthew Wakeling<> wrote:
>
> I'm seeing an interesting phenomenon while I'm trying to
> performance-optimise a GiST index. Basically, running a performance test
> appears to be the same thing as running a random number generator. For
> example, here I'm running the same statement eight times in quick
> succession:
>
>> modmine_overlap_test=# \timing
>> Timing is on.
>> modmine_overlap_test=# select count(*) from (select * FROM
>> locatedsequencefeatureoverlappingfeatures limit 1000000) AS a;
>>  count
>> ---------
>>  1000000
>> (1 row)
>>
>> Time: 138583.140 ms
>>
>> Time: 153769.152 ms
>>
>> Time: 127518.574 ms
>>
>> Time: 49629.036 ms
>>
>> Time: 70926.034 ms
>>
>> Time: 7625.034 ms
>>
>> Time: 7382.609 ms
>>
>> Time: 7985.379 ms
>
> "locatedsequencefeatureoverlappingfeatures" is a view, which performs a join
> with a GiST index. The machine was otherwise idle, and has plenty of RAM
> free.
>
> Shouldn't the data be entirely in cache the second time I run the statement?
> However, it's worse than that, because while the long-running statements
> were running, I saw significant CPU usage in top - more than eight seconds
> worth. Again, one one test there was no io-wait, but on a subsequent test
> there was lots of io-wait.
>
> How can this be so inconsistent?

Beats me.  It looks like the first few queries are pulling stuff into
cache, and then after that it settles down, but I'm not sure why it
takes 5 repetitions to do that.  Is the plan changing?

...Robert

От:
Greg Stark
Дата:

On Tue, Aug 4, 2009 at 11:56 PM, Robert Haas<> wrote:
> Beats me.  It looks like the first few queries are pulling stuff into
> cache, and then after that it settles down, but I'm not sure why it
> takes 5 repetitions to do that.  Is the plan changing?

Yeah, we're just guessing without the explain analyze output.

But as long as we're guessing, perhaps it's doing a sequential scan on
one of the tables and each query is reading in new parts of the table
until the whole table is in cache. Is this a machine with lots of RAM
but a small setting for shared_buffers?


--
greg
http://mit.edu/~gsstark/resume.pdf

От:
Matthew Wakeling
Дата:

On Wed, 5 Aug 2009, Greg Stark wrote:
> On Tue, Aug 4, 2009 at 11:56 PM, Robert Haas<> wrote:
>> Beats me.  It looks like the first few queries are pulling stuff into
>> cache, and then after that it settles down, but I'm not sure why it
>> takes 5 repetitions to do that.  Is the plan changing?
>
> Yeah, we're just guessing without the explain analyze output.
>
> But as long as we're guessing, perhaps it's doing a sequential scan on
> one of the tables and each query is reading in new parts of the table
> until the whole table is in cache. Is this a machine with lots of RAM
> but a small setting for shared_buffers?

modmine_overlap_test=# explain analyse select count(*) from (select * FROM
locatedsequencefeatureoverlappingfeatures limit 1000000) AS a;

QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
  Aggregate  (cost=478847.24..478847.25 rows=1 width=0)
             (actual time=27546.424..27546.428 rows=1 loops=1)
    ->  Limit  (cost=0.01..466347.23 rows=1000000 width=8)
               (actual time=0.104..24349.407 rows=1000000 loops=1)
          ->  Nested Loop
                       (cost=0.01..9138533.31 rows=19595985 width=8)
                       (actual time=0.099..17901.571 rows=1000000 loops=1)
                Join Filter: (l1.subjectid <> l2.subjectid)
                ->  Seq Scan on location l1
                       (cost=0.00..90092.22 rows=4030122 width=16)
                       (actual time=0.013..11.467 rows=3396 loops=1)
                ->  Index Scan using location_object_bioseg on location l2
                       (cost=0.01..1.46 rows=35 width=16)
                       (actual time=0.130..3.339 rows=295 loops=3396)
                      Index Cond: ((l2.objectid = l1.objectid) AND (bioseg_create(l1.intermine_start, l1.intermine_end)
&&bioseg_create(l2.intermine_start, l2.intermine_end))) 
  Total runtime: 27546.534 ms
(8 rows)

Time: 27574.164 ms

It is certainly doing a sequential scan. So are you saying that it will
start a sequential scan from a different part of the table each time, even
in the absence of other simultaneous sequential scans? Looks like I'm
going to have to remove the limit to get sensible results - I only added
that to make the query return in a sensible time for performance testing.

Some trivial testing with "select * from location limit 10;" indicates
that it starts the sequential scan in the same place each time - but is
this different from the above query?

To answer your question:

shared_buffers = 450MB
Machine has 16GB or RAM
The location table is 389 MB
The location_object_bioseg index is 182 MB

Matthew

--
 What goes up must come down. Ask any system administrator.

От:
Robert Haas
Дата:

On Wed, Aug 5, 2009 at 6:20 AM, Matthew Wakeling<> wrote:
> It is certainly doing a sequential scan. So are you saying that it will
> start a sequential scan from a different part of the table each time, even
> in the absence of other simultaneous sequential scans? Looks like I'm going
> to have to remove the limit to get sensible results - I only added that to
> make the query return in a sensible time for performance testing.
>
> Some trivial testing with "select * from location limit 10;" indicates that
> it starts the sequential scan in the same place each time - but is this
> different from the above query?

Maybe it's because of this?

http://www.postgresql.org/docs/8.3/static/runtime-config-compatible.html#GUC-SYNCHRONIZE-SEQSCANS

...Robert

От:
Matthew Wakeling
Дата:

On Wed, 5 Aug 2009, Robert Haas wrote:
> On Wed, Aug 5, 2009 at 6:20 AM, Matthew Wakeling<> wrote:
>> It is certainly doing a sequential scan. So are you saying that it will
>> start a sequential scan from a different part of the table each time, even
>> in the absence of other simultaneous sequential scans? Looks like I'm going
>> to have to remove the limit to get sensible results - I only added that to
>> make the query return in a sensible time for performance testing.
>>
>> Some trivial testing with "select * from location limit 10;" indicates that
>> it starts the sequential scan in the same place each time - but is this
>> different from the above query?
>
> Maybe it's because of this?
>
> http://www.postgresql.org/docs/8.3/static/runtime-config-compatible.html#GUC-SYNCHRONIZE-SEQSCANS

Thanks, we had already worked that one out. What I'm surprised about is
that it will start the sequential scan from a different part of the table
when there aren't any simultaneous scans, but not when I do the trivial
testing.

Having reduced the data quantity (so I can throw away the limit) makes my
tests produce much more consistent results. I label this problem as
solved. Thanks all.

Matthew

--
 $ rm core
 Segmentation Fault (core dumped)

От:
Tom Lane
Дата:

Matthew Wakeling <> writes:
> It is certainly doing a sequential scan. So are you saying that it will
> start a sequential scan from a different part of the table each time, even
> in the absence of other simultaneous sequential scans?

Yeah, that's the syncscan logic biting you.  You can turn it off if you
want.

> Some trivial testing with "select * from location limit 10;" indicates
> that it starts the sequential scan in the same place each time - but is
> this different from the above query?

Yup, you're not scanning enough of the table to move the syncscan start
pointer.

            regards, tom lane