patch: improve SLRU replacement algorithm

On Wed, Apr 4, 2012 at 8:00 AM, Robert Haas <robertmhaas@gmail.com> wrote:

There's some apparent regression on the single-client test, but I'm
inclined to think that's a testing artifact of some kind and also
probably not very important.  It would be worth paying a small price
in throughput to avoid many-second entire-database stalls, but on this
test throughput actually goes up in all cases other than a single
client; and it's hard to take the single client case seriously as a
regression anyway because if there's only one thing running, the only
effect of this patch is to slightly increase the amount of CPU effort
that we spend before replacement the same buffer we would have
replaced anyway.  There's no way that's enough to cut 3% off
performance; I think the explanation must be something like, say,
autovacuum runs a bit faster because it doesn't hang as much, but then
that triggers a checkpoint sooner; or something's shuffled itself
around across cache lines in a way that works out a little worse; or
maybe it's just that the patched code was tested second.

I reran the single client tests and this time got:

m01 tps = 1357.485132 (including connections establishing)
m01 tps = 1425.967027 (including connections establishing)
m01 tps = 1381.468519 (including connections establishing)
s01 tps = 1411.590074 (including connections establishing)
s01 tps = 1374.938182 (including connections establishing)
s01 tps = 1402.680618 (including connections establishing)

...which seems like ample evidence that there's no real regression
here, if anyone was still worried.

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

On Wed, Apr 4, 2012 at 1:00 PM, Robert Haas <robertmhaas@gmail.com> wrote:

, everybody's next few CLOG requests hit some other
buffer but eventually the long-I/O-in-progress buffer again becomes
least recently used and the next CLOG eviction causes a second backend
to begin waiting for that buffer.

This still sounds like evidence that the slru is just too small for
this transaction rate. Otherwise there would be some other buffer that
would be accessed similarly infrequently.

Your fix sounds right to me but I would hope it should be fixing
something that would only happen rarely, not every time theres a
write. It sounds like the slru is thrashing quite a bit more than the
code anticipates.

--
greg

On Wed, Apr 4, 2012 at 1:00 PM, Robert Haas <robertmhaas@gmail.com> wrote:

3. I noticed that the blocking described by "slru.c:311 blocked by
slru.c:405" seemed to be clumpy - I would get a bunch of messages
about that all at once.  This makes me wonder if the SLRU machinery is
occasionally making a real bad decision about what page to evict, and
then everybody piles up waiting for that page to be read back in.
That is sheer hand-waving at this point and might be complete bologna,
but I'm hoping to find time to investigate further.

Hm, actually, isn't this something your patch would cause? Is it
possible the clumpy ones are the 129 minus 54 additional blocking on this
lock in the patched code? Did it do that in the unpatched code? And
did it do it with fewer than 16 clients?

Because there are only 16 slru pages and 64 clients so occasionally 16
of clients will all be reading a page in and someone will try to flush
the very hottest page from the slru. Or I suppose it would happen
sooner as soon as someone gets pushed up into the working set and hits
a hot enough page.

i didn't actually read the patch. I assume you covered the case where
all the pages are in I/O and so there are no eligible pages to flush?

--
greg

Excerpts from Greg Stark's message of mié abr 04 14:11:29 -0300 2012:

On Wed, Apr 4, 2012 at 1:00 PM, Robert Haas <robertmhaas@gmail.com> wrote:

, everybody's next few CLOG requests hit some other
buffer but eventually the long-I/O-in-progress buffer again becomes
least recently used and the next CLOG eviction causes a second backend
to begin waiting for that buffer.

This still sounds like evidence that the slru is just too small for
this transaction rate.

What this statement means to me is that the number of slru buffers
should be configurable, not compile-time fixed.

--
Álvaro Herrera <alvherre@commandprompt.com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

On Wed, Apr 4, 2012 at 1:11 PM, Greg Stark <stark@mit.edu> wrote:

On Wed, Apr 4, 2012 at 1:00 PM, Robert Haas <robertmhaas@gmail.com> wrote:

, everybody's next few CLOG requests hit some other
buffer but eventually the long-I/O-in-progress buffer again becomes
least recently used and the next CLOG eviction causes a second backend
to begin waiting for that buffer.

This still sounds like evidence that the slru is just too small for
this transaction rate. Otherwise there would be some other buffer that
would be accessed similarly infrequently.

Your fix sounds right to me but I would hope it should be fixing
something that would only happen rarely, not every time theres a
write. It sounds like the slru is thrashing quite a bit more than the
code anticipates.

Yes, the SLRU is thrashing heavily. In this configuration, there are
32 CLOG buffers. I just added an elog() every time we replace a
buffer. Here's a sample of how often that's firing, by second, on
this test (pgbench with 32 clients):

4191 19:54:21
4540 19:54:22
4295 19:54:23
3931 19:54:24
4294 19:54:25
478 19:54:26
72 19:54:27
818 19:54:28
876 19:54:29
1498 19:54:30
3526 19:54:31
1874 19:54:32
551 19:54:35
3746 19:54:36
3846 19:54:37
3803 19:54:38
3593 19:54:39
3016 19:54:40
3233 19:54:41
3190 19:54:42
3291 19:54:43
5068 19:54:44
3877 19:54:45
2 19:54:46
1678 19:54:47
1005 19:54:48
947 19:54:49
1007 19:54:50
921 19:54:51
931 19:54:52
147 19:54:53
1103 19:54:54
898 19:54:55
674 19:54:56
274 19:54:57
1081 19:54:58
1874 19:54:59
1067 19:55:00
328 19:55:01
1507 19:55:02
3735 19:55:03
138 19:55:04
1 19:55:05
2667 19:55:09
5373 19:55:10
5175 19:55:11
5062 19:55:12

So, yes, we're thrashing CLOG pretty hard. But, I think that's a
mostly separate issue. Reworking the SLRU code so that it can
efficiently handle a larger number of buffers is probably a good thing
to do, but unless we're planning to make the CLOG SLRU so large that
we NEVER have multiple people trying to replace buffers at the same
time, this fix is still necessary and appropriate.

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

diff --git a/src/backend/access/transam/slru.c
b/src/backend/access/transam/slru.c
index 3049e01..6f92679 100644
--- a/src/backend/access/transam/slru.c
+++ b/src/backend/access/transam/slru.c
@@ -390,6 +390,9 @@ SimpleLruReadPage(SlruCtl ctl, int pageno, bool write_ok,
                        return slotno;
                }

+               elog(LOG, "SLRU %d reading page %d", shared->ControlLock,
+                       pageno);
+
                /* We found no match; assert we selected a freeable slot */
                Assert(shared->page_status[slotno] == SLRU_PAGE_EMPTY ||
                           (shared->page_status[slotno] == SLRU_PAGE_VALID &&

On Wed, Apr 4, 2012 at 1:00 PM, Robert Haas <robertmhaas@gmail.com> wrote:

I'll do some testing to try to confirm whether this theory is correct
and whether the above fix helps.

Very interesting work.

Having performed this investigation, I've discovered a couple of
interesting things.  First, SlruRecentlyUsed() is an ineffective way
of keeping a page from getting reused, because it's called extremely
frequently, and on these high-velocity tests it takes almost no time
at all for the most recently used buffer to become the least recently
used buffer.

Measurement?

Therefore, SlruRecentlyUsed() doesn't prevent the lock
pile-up.  In the unpatched code, once a long buffer I/O starts,
everybody immediately goes into the tank until the I/O finishes.  If
you patch the code so that the page is marked recently-used before
beginning the I/O, everybody's next few CLOG requests hit some other
buffer but eventually the long-I/O-in-progress buffer again becomes
least recently used and the next CLOG eviction causes a second backend
to begin waiting for that buffer.  Lather, rinse, repeat, until
literally every backend is once again waiting on that buffer I/O.  You
still get the same problem; it just takes slightly longer to develop.

Sounds believable, I just want to make sure we have measured things.

On reflection, it seems to me that the right fix here is to make
SlruSelectLRUPage() to avoid selecting a page on which an I/O is
already in progress.  In general, those I/Os are all writes.  We don't
end up waiting for reads because all the old CLOG pages we might want
to read are still in the OS cache.  So reads complete quickly, on this
test.

I believe that, but if all buffers are I/O busy we should avoid
waiting on a write I/O if possible.

 Writes take a long time, because there we have to actually get
the data down to disk, and the disk is busy.  But there's no reason
for a backend doing a replacement to wait for either a read or a write
that is in progress: once the read or write completes, we're going to
loop around and repeat the buffer selection process, and most likely
pick a buffer completely unrelated to the one whose I/O we waited for.
 We might as well just skip the wait and select that other buffer
immediately.  The attached patch implements that.

That seems much smarter. I'm thinking this should be back patched
because it appears to be fairly major, so I'm asking for some more
certainty that every thing you say here is valid. No doubt much of it
is valid, but that's not enough.

Applying this patch does in fact eliminate the stalls.

I'd like to see that measured from a user perspective. It would be
good to see the response time distribution for run with and without
the patch.

2. I think we might want to revisit Simon's idea of background-writing
SLRU pages.

Agreed. No longer anywhere near as important. I'll take a little
credit for identifying the right bottleneck, since you weren't a
believer before.

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On Wed, Apr 4, 2012 at 6:25 PM, Alvaro Herrera
<alvherre@commandprompt.com> wrote:

Excerpts from Greg Stark's message of mié abr 04 14:11:29 -0300 2012:

On Wed, Apr 4, 2012 at 1:00 PM, Robert Haas <robertmhaas@gmail.com> wrote:

, everybody's next few CLOG requests hit some other
buffer but eventually the long-I/O-in-progress buffer again becomes
least recently used and the next CLOG eviction causes a second backend
to begin waiting for that buffer.

This still sounds like evidence that the slru is just too small for
this transaction rate.

What this statement means to me is that the number of slru buffers
should be configurable, not compile-time fixed.

I think the compile time fixed allows it to be loop unrolled and
executed in parallel.

Using a parameter makes the lookups slower. Worth testing. Life changes.

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On Wed, Apr 4, 2012 at 9:05 PM, Robert Haas <robertmhaas@gmail.com> wrote:

Yes, the SLRU is thrashing heavily.  In this configuration, there are
32 CLOG buffers.  I just added an elog() every time we replace a
buffer.  Here's a sample of how often that's firing, by second, on
this test (pgbench with 32 clients):

Interesting. You've spoken at length how this hardly ever happens and
so this can't have any performance effect. That was the reason for
kicking out my patch addressing clog history, wasn't it?

Why is this pgbench run accessing so much unhinted data that is > 1
million transactions old? Do you believe those numbers? Looks weird.

Perhaps we should retest the clog history patch?

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On Wed, Apr 4, 2012 at 9:34 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Why is this pgbench run accessing so much unhinted data that is > 1
million transactions old? Do you believe those numbers? Looks weird.

I think this is in the nature of the workload pgbench does. Because
the updates are uniformly distributed, not concentrated 90% in 10% of
the buffers like most real-world systems, (and I believe pgbench only
does index lookups) the second time a tuple is looked at is going to
average N/2 transactions later where N is the number of tuples. Given
a scale factor of 300 that's 15 million transactions.

More aggressively hinting other tuples on the page that we have no
other business looking at might help, though that would require extra
finess to avoid causing extra clog reads. Presumably you would only
want to hint other tuples whose xids were in clog pages that were
actually in memory currently.

--
greg

On Wed, Apr 4, 2012 at 9:05 PM, Robert Haas <robertmhaas@gmail.com> wrote:

Here's a sample of how often that's firing, by second, on
this test (pgbench with 32 clients):

  4191 19:54:21
  4540 19:54:22

Hm, so if that's evenly spread out that's 1/4ms between slru flushes
and if each flush takes 5-10ms that's going to be 20-40 flushes
concurrently going on.

I'm curious to see a distribution of how many flushes are already
concurrently happening whenever a flush is initiated. This should be
possible to get by counting the number of pages that were skipped in
your patch as it went through the slru.

Also, oops, sorry. I mixed up the 32 clog buffers with the 16 files
that the slru.c remembers during a flush to fsync later. I still don't
understand why it doesn't just allocate enough space to remember to
fsync the worst case which is one file per clog buffer though which
would only be twice as many.

--
greg

Greg Stark <stark@mit.edu> writes:

On Wed, Apr 4, 2012 at 9:34 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Why is this pgbench run accessing so much unhinted data that is > 1
million transactions old? Do you believe those numbers? Looks weird.

I think this is in the nature of the workload pgbench does. Because
the updates are uniformly distributed, not concentrated 90% in 10% of
the buffers like most real-world systems, (and I believe pgbench only
does index lookups) the second time a tuple is looked at is going to
average N/2 transactions later where N is the number of tuples.

That's a good point, and it makes me wonder whether pgbench is the right
test case to be micro-optimizing around. It would be a good idea to at
least compare the numbers for something with more locality of reference.

regards, tom lane

On 4/4/12 4:02 PM, Tom Lane wrote:

Greg Stark <stark@mit.edu> writes:

On Wed, Apr 4, 2012 at 9:34 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Why is this pgbench run accessing so much unhinted data that is > 1
million transactions old? Do you believe those numbers? Looks weird.

I think this is in the nature of the workload pgbench does. Because
the updates are uniformly distributed, not concentrated 90% in 10% of
the buffers like most real-world systems, (and I believe pgbench only
does index lookups) the second time a tuple is looked at is going to
average N/2 transactions later where N is the number of tuples.

That's a good point, and it makes me wonder whether pgbench is the right
test case to be micro-optimizing around. It would be a good idea to at
least compare the numbers for something with more locality of reference.

Jignesh, would DVDstore help for this?

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com

On Wed, Apr 4, 2012 at 4:23 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Measurement?

Sounds believable, I just want to make sure we have measured things.

Yes, I measured things. I didn't post the results because they're
almost identical to the previous set of results which I already
posted. That is, I wrote the patch; I ran it through the
instrumentation framework; the same long waits with the same set of
file/line combinations were still present. Then I wrote the patch
that is attached to the OP, and also tested that, and those long waits
went away completely.

I believe that, but if all buffers are I/O busy we should avoid
waiting on a write I/O if possible.

I thought about that, but I don't see that there's any point in
further complicating the algorithm. The current patch eliminates ALL
the long waits present in this code path, which means that the
situation where every CLOG buffer is I/O-busy at the same time either
never happens, or never causes any significant stalls. I think it's a
bad idea to make this any more complicated than is necessary to do the
right thing in real-world cases.

That seems much smarter. I'm thinking this should be back patched
because it appears to be fairly major, so I'm asking for some more
certainty that every thing you say here is valid. No doubt much of it
is valid, but that's not enough.

Yeah, I was thinking about that. What we're doing right now seems
pretty stupid, so maybe it's worth considering a back-patch. OTOH,
I'm usually loathe to tinker with performance in stable releases.
I'll defer to the opinions of others on this point.

Applying this patch does in fact eliminate the stalls.

I'd like to see that measured from a user perspective. It would be
good to see the response time distribution for run with and without
the patch.

My feeling is that you're not going to see very much difference in a
latency-by-second graph, because XLogInsert is responsible for lots
and lots of huge stalls also. That's going to mask the impact of
fixing this problem. However, it's not much work to run the test, so
I'll do that.

2. I think we might want to revisit Simon's idea of background-writing
SLRU pages.

Agreed. No longer anywhere near as important. I'll take a little
credit for identifying the right bottleneck, since you weren't a
believer before.

I don't think I ever said it was a bad idea; I just couldn't measure
any benefit. I think now we know why, or at least have a clue; and
maybe some ideas about how to measure it better.

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

On Wed, Apr 4, 2012 at 4:34 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Interesting. You've spoken at length how this hardly ever happens and
so this can't have any performance effect. That was the reason for
kicking out my patch addressing clog history, wasn't it?

Uh, no, the reason for kicking out your clog history patch was that it
caused throughput to drop by a factor of 3 on a pgbench test at scale
factor 300. I assume you've got a bug there somewhere, or maybe
there's some other effect that hasn't been quantified.

Why is this pgbench run accessing so much unhinted data that is > 1
million transactions old? Do you believe those numbers? Looks weird.

Seems pretty normal to me, for the reasons Greg Stark states.

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

On Wed, Apr 4, 2012 at 7:02 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Greg Stark <stark@mit.edu> writes:

On Wed, Apr 4, 2012 at 9:34 PM, Simon Riggs <simon@2ndquadrant.com> wrote:

Why is this pgbench run accessing so much unhinted data that is > 1
million transactions old? Do you believe those numbers? Looks weird.

I think this is in the nature of the workload pgbench does. Because
the updates are uniformly distributed, not concentrated 90% in 10% of
the buffers like most real-world systems, (and I believe pgbench only
does index lookups) the second time a tuple is looked at is going to
average N/2 transactions later where N is the number of tuples.

That's a good point, and it makes me wonder whether pgbench is the right
test case to be micro-optimizing around.  It would be a good idea to at
least compare the numbers for something with more locality of reference.

I agree that there are other benchmarks that are worth optimizing for,
but this particular change is more in the nature of a bug fix. The
current code is waiting for an I/O on buffer A when there's no real
need and we're going afterwards proceed to NOT select buffer A anyway
(or at least, with no more probability than that it will select any
other buffer).

I don't think we're micro-optimizing, either. I don't consider
avoiding a 10-second cessation of all database activity to be a
micro-optimization even on a somewhat artificial benchmark.

One other thing to think about is that pgbench at scale factor 300 is
not exactly a large working set. You could easily imagine a
real-world data set that is more the size of scale factor 3000, and
10% of it is hot, and you'd have pretty much the same problem. The
indexes would be a little deeper and so on, but I see no reason why
you wouldn't be able to reproduce this effect with the right test
set-up. I am sure there will come a point when we've learned as much
as we can from pgbench and must graduate to more complex benchmarks to
have any hope of finding problems worth fixing, but we are surely
still quite a long ways off from that happy day.

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

On Thu, Apr 5, 2012 at 1:23 AM, Robert Haas <robertmhaas@gmail.com> wrote:

I don't think we're micro-optimizing, either.  I don't consider
avoiding a 10-second cessation of all database activity to be a
micro-optimization even on a somewhat artificial benchmark.

Robert is not skewing the SLRU mechanism towards this case, he is
simply fixing something so gross that "bug" is the only word for it,
and that shows up clearly on this test. I'm happy that the fix
proposed has general utility without negative impact on other
workloads.

In general terms, I agree we shouldn't rely on pgbench as a general
workload, nor should we solely tune Postgres for throughput without
regard to response time. But that point is not relevant to this
specific issue.

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On Thu, Apr 5, 2012 at 12:25 AM, Robert Haas <robertmhaas@gmail.com> wrote:

That seems much smarter. I'm thinking this should be back patched
because it appears to be fairly major, so I'm asking for some more
certainty that every thing you say here is valid. No doubt much of it
is valid, but that's not enough.

Yeah, I was thinking about that.  What we're doing right now seems
pretty stupid, so maybe it's worth considering a back-patch.  OTOH,
I'm usually loathe to tinker with performance in stable releases.
I'll defer to the opinions of others on this point.

I'm also loathe to back patch. But its not very often we find a
problem that causes all backends to wait behind a single I/O.

The wait-behind-I/O aspect is "OK" because that is what is designed to
happen. The unexpected bit is the point that the system *quickly*
switches around so that *all* backends choose to wait behind that same
I/O, which is mad.

There is no doubt that your I/Os are slow here and that the specific
test accentuates that, but neither of those things are rare.

If it was an optimiser bug that made something run in 10sec that
should have run in 10ms we fix it. So we fix this also.

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services

On Thu, Apr 5, 2012 at 5:41 AM, Simon Riggs <simon@2ndquadrant.com> wrote:

I'm also loathe to back patch. But its not very often we find a
problem that causes all backends to wait behind a single I/O.

You have a point.

Meanwhile, here are the benchmark results you requested. I did half
hour runs with -l. Here are the 90th-100th percentile latencies,
without patch and then with patch.

90 1668 1620
91 1747 1690
92 1845 1785
93 1953 1907
94 2064 2035
95 2176 2160
96 2300 2291
97 2461 2451
98 2739 2710
99 3542 3495
100 12955473 19072385

Overall tps, first without and then with patch:

tps = 14546.644712 (including connections establishing)
tps = 14550.515173 (including connections establishing)

TPS graphs by second attached.

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

On Thu, Apr 5, 2012 at 12:56 PM, Robert Haas <robertmhaas@gmail.com> wrote:

Overall tps, first without and then with patch:

tps = 14546.644712 (including connections establishing)
tps = 14550.515173 (including connections establishing)

TPS graphs by second attached.

Again, I'm not that fussed about throughput because it just hides the
detail. I am concerned about the distribution of response times, so
I'd like to see the numbers about that if you don't mind. i.e. does
the patch remove long waits.

--
 Simon Riggs                   http://www.2ndQuadrant.com/
 PostgreSQL Development, 24x7 Support, Training & Services