Small bug in replication lag tracking
Hi,
I discovered a thinko in the new replication lag interpolation code
that can cause a strange number to be reported occasionally.
The interpolation code is designed to report increasing lag when
replay gets stuck somewhere between two LSNs for which we have
timestamp samples. The bug is that after sitting idle and fully
replayed for a while and then encountering a new burst of WAL
activity, we interpolate between an ancient sample and the
not-yet-reached one for the new traffic, which is inappropriate. It's
hard to see obviously strange lag times, because they normally only
exist for a very short moment in between receiving the first and
second replies from the standby, and they often look reasonable even
if you do manage to catch one in pg_stat_replication. You can see the
problem by pausing replay on the the standby in between two bursts of
WAL with a long period of idleness in between.
Please find attached a patch to fix that, with comments to explain.
--
Thomas Munro
http://www.enterprisedb.com
Attachments:
fix-lag-interpolation-bug.patchapplication/octet-stream; name=fix-lag-interpolation-bug.patchDownload
diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index 82f7b593734..f845180873e 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -3443,6 +3443,16 @@ LagTrackerRead(int head, XLogRecPtr lsn, TimestampTz now)
(LagTracker.read_heads[head] + 1) % LAG_TRACKER_BUFFER_SIZE;
}
+ /*
+ * If the lag tracker is empty, that means the standby has processed
+ * everything we've ever sent so we should now clear 'last_read'. If we
+ * didn't do that, we'd risk using a stale and irrelevant sample for
+ * interpolation at the beginning of the next burst of WAL after a period
+ * of idleness.
+ */
+ if (LagTracker.read_heads[head] == LagTracker.write_head)
+ LagTracker.last_read[head].time = 0;
+
if (time > now)
{
/* If the clock somehow went backwards, treat as not found. */
@@ -3459,9 +3469,14 @@ LagTrackerRead(int head, XLogRecPtr lsn, TimestampTz now)
* eventually start moving again and cross one of our samples before
* we can show the lag increasing.
*/
- if (LagTracker.read_heads[head] != LagTracker.write_head &&
- LagTracker.last_read[head].time != 0)
+ if (LagTracker.read_heads[head] == LagTracker.write_head)
{
+ /* There are no future samples, so we can't interpolate. */
+ return -1;
+ }
+ else if (LagTracker.last_read[head].time != 0)
+ {
+ /* We can interpolate between last_read and the next sample. */
double fraction;
WalTimeSample prev = LagTracker.last_read[head];
WalTimeSample next = LagTracker.buffer[LagTracker.read_heads[head]];
@@ -3494,8 +3509,14 @@ LagTrackerRead(int head, XLogRecPtr lsn, TimestampTz now)
}
else
{
- /* Couldn't interpolate due to lack of data. */
- return -1;
+ /*
+ * We have only a future sample, implying that we were entirely
+ * caught up but and now there is a new burst of WAL and the
+ * standby hasn't processed the first sample yet. Until the
+ * standby reaches the future sample the best we can do is report
+ * the hypothetical lag if that sample were to be replayed now.
+ */
+ time = LagTracker.buffer[LagTracker.read_heads[head]].time;
}
}
On 23 June 2017 at 06:45, Thomas Munro <thomas.munro@enterprisedb.com> wrote:
I discovered a thinko in the new replication lag interpolation code
that can cause a strange number to be reported occasionally.
Thanks, will review.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On 23 June 2017 at 08:18, Simon Riggs <simon@2ndquadrant.com> wrote:
On 23 June 2017 at 06:45, Thomas Munro <thomas.munro@enterprisedb.com> wrote:
I discovered a thinko in the new replication lag interpolation code
that can cause a strange number to be reported occasionally.Thanks, will review.
I've pushed this, but I think we should leave the code alone after
this and wait for user feedback.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Sat, Jun 24, 2017 at 6:07 AM, Simon Riggs <simon@2ndquadrant.com> wrote:
On 23 June 2017 at 08:18, Simon Riggs <simon@2ndquadrant.com> wrote:
On 23 June 2017 at 06:45, Thomas Munro <thomas.munro@enterprisedb.com> wrote:
I discovered a thinko in the new replication lag interpolation code
that can cause a strange number to be reported occasionally.Thanks, will review.
I've pushed this, but I think we should leave the code alone after
this and wait for user feedback.
Thanks! Yeah, I haven't heard any feedback about this, which I've
been interpreting as good news... but if anyone's looking for
something to beta test, reports would be most welcome.
--
Thomas Munro
http://www.enterprisedb.com
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers