Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

On Fri, Apr 1, 2016 at 10:02 AM, Michael Paquier
 wrote:
> On Fri, Apr 1, 2016 at 4:14 AM, Alvaro Herrera  
> wrote:
>> Noah Misch wrote:
>>
>>> The above-described topic is currently a PostgreSQL 9.6 open item.  Alvaro,
>>> since you committed the patch believed to have created it, you own this open
>>> item.
>>
>> That's correct.  Since we already had a patch available, I pushed it.
>> I'll wait for a few days before marking the open item as closed in the
>> wiki, to make sure that hamster reports success a few times.
>
> Thanks. I just did a couple of additional manual tests on hamster, and
> the sporadic failure does not show up anymore, so the daily runs
> should be in good shape now for this test.

The failing test has passed 7 days in a row, so I am marking this
issue as fixed.
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

On Fri, Apr 1, 2016 at 4:14 AM, Alvaro Herrera  wrote:
> Noah Misch wrote:
>
>> The above-described topic is currently a PostgreSQL 9.6 open item.  Alvaro,
>> since you committed the patch believed to have created it, you own this open
>> item.
>
> That's correct.  Since we already had a patch available, I pushed it.
> I'll wait for a few days before marking the open item as closed in the
> wiki, to make sure that hamster reports success a few times.

Thanks. I just did a couple of additional manual tests on hamster, and
the sporadic failure does not show up anymore, so the daily runs
should be in good shape now for this test.
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Alvaro Herrera]

Noah Misch wrote:

> The above-described topic is currently a PostgreSQL 9.6 open item.  Alvaro,
> since you committed the patch believed to have created it, you own this open
> item.

That's correct.  Since we already had a patch available, I pushed it.
I'll wait for a few days before marking the open item as closed in the
wiki, to make sure that hamster reports success a few times.

-- 
Álvaro Herrerahttp://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

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Alvaro Herrera]

Michael Paquier wrote:

> Actually, the attached is better. This one relies on time() to perform
> the delay checks, and takes care of things even for slow machines.

Thanks, pushed with some minor adjustments.

-- 
Álvaro Herrerahttp://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

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Noah Misch]

On Sun, Mar 13, 2016 at 10:18:46PM +0100, Michael Paquier wrote:
> On Wed, Mar 9, 2016 at 9:05 PM, Michael Paquier
>  wrote:
> > On Wed, Mar 9, 2016 at 12:29 PM, Alvaro Herrera
> >  wrote:
> >> Michael Paquier wrote:
> >>> After sleeping (best debugger ever) on that, actually a way popped up
> >>> in my mind, and I propose the attached, which refactors a bit 005 and
> >>> checks that the LSN position of master has been applied on standby
> >>> after at least the delay wanted. A maximum delay of 90s is authorized,
> >>> like poll_query_until.
> >>
> >> Hmm, okay, that's great.  A question: what happens if the test itself is
> >> slow and the servers are fast, and the test doesn't manage to run two
> >> iterations before the two seconds have elapsed?  This may happen on
> >> overloaded or slow servers, if you're unlucky.
> >
> > Yes, a failure would happen. The same thought occurred to me during a
> > long flight. And this is why the previous patch was full of meh.
> >
> >> I don't have any ideas on ensuring that we don't apply earlier than the
> >> given period at the moment.
> >
> > Attached is one, which is based on timestamp values queried from the
> > standby server. We could use as well perl's localtime call to
> > calculate the time delay.
> 
> Actually, the attached is better. This one relies on time() to perform
> the delay checks, and takes care of things even for slow machines.

[This is a generic notification.]

The above-described topic is currently a PostgreSQL 9.6 open item.  Alvaro,
since you committed the patch believed to have created it, you own this open
item.  If that responsibility lies elsewhere, please let us know whose
responsibility it is to fix this.  Since new open items may be discovered at
any time and I want to plan to have them all fixed well in advance of the ship
date, I will appreciate your efforts toward speedy resolution.  Please
present, within 72 hours, a plan to fix the defect within seven days of this
message.  Thanks.


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

On Wed, Mar 9, 2016 at 9:05 PM, Michael Paquier
 wrote:
> On Wed, Mar 9, 2016 at 12:29 PM, Alvaro Herrera
>  wrote:
>> Michael Paquier wrote:
>>> After sleeping (best debugger ever) on that, actually a way popped up
>>> in my mind, and I propose the attached, which refactors a bit 005 and
>>> checks that the LSN position of master has been applied on standby
>>> after at least the delay wanted. A maximum delay of 90s is authorized,
>>> like poll_query_until.
>>
>> Hmm, okay, that's great.  A question: what happens if the test itself is
>> slow and the servers are fast, and the test doesn't manage to run two
>> iterations before the two seconds have elapsed?  This may happen on
>> overloaded or slow servers, if you're unlucky.
>
> Yes, a failure would happen. The same thought occurred to me during a
> long flight. And this is why the previous patch was full of meh.
>
>> I don't have any ideas on ensuring that we don't apply earlier than the
>> given period at the moment.
>
> Attached is one, which is based on timestamp values queried from the
> standby server. We could use as well perl's localtime call to
> calculate the time delay.

Actually, the attached is better. This one relies on time() to perform
the delay checks, and takes care of things even for slow machines.
-- 
Michael
diff --git a/src/test/recovery/t/005_replay_delay.pl b/src/test/recovery/t/005_replay_delay.pl
index 986851b..78bcff6 100644
--- a/src/test/recovery/t/005_replay_delay.pl
+++ b/src/test/recovery/t/005_replay_delay.pl
@@ -3,7 +3,7 @@ use strict;
 use warnings;
 use PostgresNode;
 use TestLib;
-use Test::More tests => 2;
+use Test::More tests => 1;
 
 # Initialize master node
 my $node_master = get_new_node('master');
@@ -28,22 +28,41 @@ recovery_min_apply_delay = '2s'
 ));
 $node_standby->start;
 
-# Make new content on master and check its presence in standby
-# depending on the delay of 2s applied above.
+# Make new content on master and check its presence in standby depending
+# on the delay of 2s applied above. Before doing the insertion, get the
+# current timestamp that will be used as a comparison base. Even on slow
+# machines, this allows to have a predictable behavior when comparing the
+# delay between data insertion moment on master and replay time on standby.
+my $standby_insert_time = time();
 $node_master->safe_psql('postgres',
 	"INSERT INTO tab_int VALUES (generate_series(11,20))");
-sleep 1;
 
-# Here we should have only 10 rows
-my $result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(10), 'check content with delay of 1s');
-
-# Now wait for replay to complete on standby
+# Now wait for replay to complete on standby. We leave once check the
+# previously saved LSN of master has been applied, and then compare the
+# insertion timestamp with the current one.
 my $until_lsn =
   $node_master->safe_psql('postgres', "SELECT pg_current_xlog_location();");
-my $caughtup_query =
-  "SELECT '$until_lsn'::pg_lsn <= pg_last_xlog_replay_location()";
-$node_standby->poll_query_until('postgres', $caughtup_query)
-  or die "Timed out while waiting for standby to catch up";
-$result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(20), 'check content with delay of 2s');
+
+my $max_attempts = 90;
+my $attempts = 0;
+while ($attempts < $max_attempts)
+{
+	my $replay_status =
+	  $node_standby->safe_psql('postgres',
+		"SELECT (pg_last_xlog_replay_location() - '$until_lsn'::pg_lsn) >= 0;");
+
+	# Leave now if standby has replayed at least up to the point of
+	# master. It's time to see if data has been applied after the wanted
+	# delay.
+	last if $replay_status eq 't';
+
+	sleep 1;
+	$attempts++;
+}
+
+die "Maximum number of attempts reached" if $attempts >= $max_attempts;
+
+# This test is valid only if LSN has been applied with at least
+# the minimum apply delay expected.
+ok(time() - $standby_insert_time >= 2,
+   'Check if WAL is applied on standby after delay of 2s');

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

On Wed, Mar 9, 2016 at 12:29 PM, Alvaro Herrera
 wrote:
> Michael Paquier wrote:
>> After sleeping (best debugger ever) on that, actually a way popped up
>> in my mind, and I propose the attached, which refactors a bit 005 and
>> checks that the LSN position of master has been applied on standby
>> after at least the delay wanted. A maximum delay of 90s is authorized,
>> like poll_query_until.
>
> Hmm, okay, that's great.  A question: what happens if the test itself is
> slow and the servers are fast, and the test doesn't manage to run two
> iterations before the two seconds have elapsed?  This may happen on
> overloaded or slow servers, if you're unlucky.

Yes, a failure would happen. The same thought occurred to me during a
long flight. And this is why the previous patch was full of meh.

> I don't have any ideas on ensuring that we don't apply earlier than the
> given period at the moment.

Attached is one, which is based on timestamp values queried from the
standby server. We could use as well perl's localtime call to
calculate the time delay.
-- 
Michael
diff --git a/src/test/recovery/t/005_replay_delay.pl b/src/test/recovery/t/005_replay_delay.pl
index 986851b..74d3c91 100644
--- a/src/test/recovery/t/005_replay_delay.pl
+++ b/src/test/recovery/t/005_replay_delay.pl
@@ -3,7 +3,7 @@ use strict;
 use warnings;
 use PostgresNode;
 use TestLib;
-use Test::More tests => 2;
+use Test::More tests => 1;
 
 # Initialize master node
 my $node_master = get_new_node('master');
@@ -32,18 +32,40 @@ $node_standby->start;
 # depending on the delay of 2s applied above.
 $node_master->safe_psql('postgres',
 	"INSERT INTO tab_int VALUES (generate_series(11,20))");
-sleep 1;
 
-# Here we should have only 10 rows
-my $result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(10), 'check content with delay of 1s');
-
-# Now wait for replay to complete on standby
+# Now wait for replay to complete on standby. We check if the current
+# LSN of master has been applied after at least 2s. This uses timestamps
+# to be sure that at least the delay time has passed, as on slow machines
+# it may take more than the delay time to reach the first attempt loop.
 my $until_lsn =
   $node_master->safe_psql('postgres', "SELECT pg_current_xlog_location();");
-my $caughtup_query =
-  "SELECT '$until_lsn'::pg_lsn <= pg_last_xlog_replay_location()";
-$node_standby->poll_query_until('postgres', $caughtup_query)
-  or die "Timed out while waiting for standby to catch up";
-$result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(20), 'check content with delay of 2s');
+my $standby_insert_time =
+  $node_standby->safe_psql('postgres', "SELECT now();");
+
+my $max_attempts = 90;
+my $attempts = 0;
+my $delay_status = 0;
+while ($attempts < $max_attempts)
+{
+	my $replay_status =
+	  $node_standby->safe_psql('postgres',
+		"SELECT (pg_last_xlog_replay_location() - '$until_lsn'::pg_lsn) >= 0;");
+	my $delay_applied =
+	  $node_standby->safe_psql('postgres',
+		"SELECT now() - '$standby_insert_time'::timestamptz >= interval '2s';");
+	$delay_status = $delay_applied eq 't' ? 1 : 0;
+
+	# Leave now if standby has replayed at least up to the point of
+	# master. It's time to see if data has been applied after the wanted
+	# delay.
+	last if $replay_status eq 't';
+
+	sleep 1;
+	$attempts++;
+}
+
+die "Maximum number of attempts reached" if $attempts >= $max_attempts;
+
+# This test is valid only if LSN has been applied with at least
+# the minimum apply delay expected.
+ok($delay_status, 'Check if WAL is applied on standby after delay of 2s');

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Alvaro Herrera]

Michael Paquier wrote:
> On Wed, Mar 9, 2016 at 12:14 AM, Alvaro Herrera
>  wrote:
> > Is there anything we can do to short-circuit the wait in the case that
> > replication happens promptly?  A one-minute wait would be acceptable we
> > terminate it early by checking every second.
> 
> After sleeping (best debugger ever) on that, actually a way popped up
> in my mind, and I propose the attached, which refactors a bit 005 and
> checks that the LSN position of master has been applied on standby
> after at least the delay wanted. A maximum delay of 90s is authorized,
> like poll_query_until.

Hmm, okay, that's great.  A question: what happens if the test itself is
slow and the servers are fast, and the test doesn't manage to run two
iterations before the two seconds have elapsed?  This may happen on
overloaded or slow servers, if you're unlucky.

I don't have any ideas on ensuring that we don't apply earlier than the
given period at the moment.

-- 
Álvaro Herrerahttp://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

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

On Wed, Mar 9, 2016 at 12:14 AM, Alvaro Herrera
 wrote:
> Is there anything we can do to short-circuit the wait in the case that
> replication happens promptly?  A one-minute wait would be acceptable we
> terminate it early by checking every second.

After sleeping (best debugger ever) on that, actually a way popped up
in my mind, and I propose the attached, which refactors a bit 005 and
checks that the LSN position of master has been applied on standby
after at least the delay wanted. A maximum delay of 90s is authorized,
like poll_query_until.
-- 
Michael
diff --git a/src/test/recovery/t/005_replay_delay.pl b/src/test/recovery/t/005_replay_delay.pl
index 986851b..f95b5ab 100644
--- a/src/test/recovery/t/005_replay_delay.pl
+++ b/src/test/recovery/t/005_replay_delay.pl
@@ -3,7 +3,7 @@ use strict;
 use warnings;
 use PostgresNode;
 use TestLib;
-use Test::More tests => 2;
+use Test::More tests => 1;
 
 # Initialize master node
 my $node_master = get_new_node('master');
@@ -32,18 +32,30 @@ $node_standby->start;
 # depending on the delay of 2s applied above.
 $node_master->safe_psql('postgres',
 	"INSERT INTO tab_int VALUES (generate_series(11,20))");
-sleep 1;
 
-# Here we should have only 10 rows
-my $result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(10), 'check content with delay of 1s');
-
-# Now wait for replay to complete on standby
+# Now wait for replay to complete on standby. We check if the current
+# LSN of master has been applied after at least 2s.
 my $until_lsn =
   $node_master->safe_psql('postgres', "SELECT pg_current_xlog_location();");
-my $caughtup_query =
-  "SELECT '$until_lsn'::pg_lsn <= pg_last_xlog_replay_location()";
-$node_standby->poll_query_until('postgres', $caughtup_query)
-  or die "Timed out while waiting for standby to catch up";
-$result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(20), 'check content with delay of 2s');
+
+my $max_attempts = 90;
+my $attempts = 0;
+while ($attempts < $max_attempts)
+{
+	my $replay_status =
+	  $node_standby->safe_psql('postgres',
+		"SELECT (pg_last_xlog_replay_location() - '$until_lsn'::pg_lsn) >= 0");
+
+	# Leave now if standby has replayed at least up to the point of
+	# master.
+	last if $replay_status eq 't';
+
+	sleep 1;
+	$attempts++;
+}
+
+die "Maximum number of attempts reached" if $attempts >= $max_attempts;
+
+# This test is valid only if LSN has been applied with at least
+# the minimum apply delay expected.
+ok($attempts >= 2, 'Check if LSN is applied on standby after 2s');

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Alvaro Herrera]

Michael Paquier wrote:
> On Wed, Mar 2, 2016 at 2:04 PM, Michael Paquier
>  wrote:
> > Here are a couple of ways to address this problem:
> > 1) Remove the check before applying the delay
> > 2) Increase recovery_min_apply_delay to a time that will allow even
> > slow machines to see a difference. By experience with the other tests
> > 30s would be enough. The sleep time needs to be increased as well,
> > making the time taken for the test to run longer
> > 3) Remove all together 005, because doing either 1) or 2) reduces the
> > value of the test.
> > I'd like 1) personally, I still see value in this test.
> 
> So, as doing 1) would be actually equivalent to simply having a master
> and checking that its standby replicates correctly, I have been
> looking at 2) to see to how long the delay has to be set to make the
> test failure-proof. After doing some measurements with hamster, 10s
> and 15s have proved to not be enough unfortunately, 20s has not failed
> in 10 attempts though. Attached is a patch to bump it to 20s, though I
> would not complain if the test is actually removed to accelerate the
> runs of this test suite.

Is there anything we can do to short-circuit the wait in the case that
replication happens promptly?  A one-minute wait would be acceptable we
terminate it early by checking every second.

-- 
Álvaro Herrerahttp://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

Re: [HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

On Wed, Mar 2, 2016 at 2:04 PM, Michael Paquier
 wrote:
> Here are a couple of ways to address this problem:
> 1) Remove the check before applying the delay
> 2) Increase recovery_min_apply_delay to a time that will allow even
> slow machines to see a difference. By experience with the other tests
> 30s would be enough. The sleep time needs to be increased as well,
> making the time taken for the test to run longer
> 3) Remove all together 005, because doing either 1) or 2) reduces the
> value of the test.
> I'd like 1) personally, I still see value in this test.

So, as doing 1) would be actually equivalent to simply having a master
and checking that its standby replicates correctly, I have been
looking at 2) to see to how long the delay has to be set to make the
test failure-proof. After doing some measurements with hamster, 10s
and 15s have proved to not be enough unfortunately, 20s has not failed
in 10 attempts though. Attached is a patch to bump it to 20s, though I
would not complain if the test is actually removed to accelerate the
runs of this test suite.
-- 
Michael
diff --git a/src/test/recovery/t/005_replay_delay.pl b/src/test/recovery/t/005_replay_delay.pl
index 986851b..9b25f9e 100644
--- a/src/test/recovery/t/005_replay_delay.pl
+++ b/src/test/recovery/t/005_replay_delay.pl
@@ -24,19 +24,18 @@ $node_standby->init_from_backup($node_master, $backup_name,
 	has_streaming => 1);
 $node_standby->append_conf(
 	'recovery.conf', qq(
-recovery_min_apply_delay = '2s'
+recovery_min_apply_delay = '20s'
 ));
 $node_standby->start;
 
 # Make new content on master and check its presence in standby
-# depending on the delay of 2s applied above.
+# depending on the delay of 20s applied above.
 $node_master->safe_psql('postgres',
 	"INSERT INTO tab_int VALUES (generate_series(11,20))");
-sleep 1;
 
 # Here we should have only 10 rows
 my $result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(10), 'check content with delay of 1s');
+is($result, qq(10), 'check content with no delay');
 
 # Now wait for replay to complete on standby
 my $until_lsn =
@@ -46,4 +45,4 @@ my $caughtup_query =
 $node_standby->poll_query_until('postgres', $caughtup_query)
   or die "Timed out while waiting for standby to catch up";
 $result = $node_standby->safe_psql('postgres', "SELECT count(*) FROM tab_int");
-is($result, qq(20), 'check content with delay of 2s');
+is($result, qq(20), 'check content with delay of 20s');

-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

[HACKERS] Recovery test failure for recovery_min_apply_delay on hamster

[Michael Paquier]

Hi all,

I have enabled yesterday the recovery test suite on hamster, and we
did not have to wait long before seeing the first failure on it, the
machine being slow as hell so it is quite good at catching race
conditions:
http://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamster=2016-03-01%2016%3A00%3A06
Honestly, I did runs on this machine of the test suite, but I didn't
see it, so that's quite sporadic. Yesterday's run worked fine for
example.

In more details, the following problem showed up:
### Running SQL command on node "standby": SELECT count(*) FROM tab_int
not ok 1 - check content with delay of 1s

#   Failed test 'check content with delay of 1s'
#   at t/005_replay_delay.pl line 39.
#  got: '20'
# expected: '10'
### Running SQL command on node "master": SELECT pg_current_xlog_location();
### Running SQL command on node "standby": SELECT count(*) FROM tab_int
ok 2 - check content with delay of 2s

This is a timing issue, caused by the use of recovery_min_apply_delay,
the test doing the following:
1) Set up recovery_min_apply_delay to 2 seconds
2) Start the standby
3) Apply an INSERT on master, save pg_current_xlog_location from master
4) sleep 1s
5) query standby, and wait that WAL has not been applied yet.
6) Wait that required LSN from master has been applied
7) query again standby, and see that WAL has been applied.

The problem is that visibly hamster is so slow that more than 2s have
been spent between phases 3 and 5, meaning that the delay has already
been reached, and WAL was applied.

Here are a couple of ways to address this problem:
1) Remove the check before applying the delay
2) Increase recovery_min_apply_delay to a time that will allow even
slow machines to see a difference. By experience with the other tests
30s would be enough. The sleep time needs to be increased as well,
making the time taken for the test to run longer
3) Remove all together 005, because doing either 1) or 2) reduces the
value of the test.
I'd like 1) personally, I still see value in this test.

Thoughts?
-- 
Michael


-- 
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers