Обсуждение: GiST, caching, and consistency
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
On Tue, Aug 4, 2009 at 12:06 PM, Matthew Wakeling<matthew@flymine.org> 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
On Tue, Aug 4, 2009 at 11:56 PM, Robert Haas<robertmhaas@gmail.com> 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
On Wed, 5 Aug 2009, Greg Stark wrote: > On Tue, Aug 4, 2009 at 11:56 PM, Robert Haas<robertmhaas@gmail.com> 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.
On Wed, Aug 5, 2009 at 6:20 AM, Matthew Wakeling<matthew@flymine.org> 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
On Wed, 5 Aug 2009, Robert Haas wrote: > On Wed, Aug 5, 2009 at 6:20 AM, Matthew Wakeling<matthew@flymine.org> 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)
Matthew Wakeling <matthew@flymine.org> 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