Horton

Thread

Commits

  1. Fix bogus cache-invalidation logic in logical replication worker.

  1. Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-09-14T15:20:03Z

    In connection with a nearby thread, I tried to run the subscription
test suite in a CLOBBER_CACHE_ALWAYS build.  I soon found that I had
to increase wal_receiver_timeout, but after doing this:

diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm
index 1488bff..5fe6810 100644
*** a/src/test/perl/PostgresNode.pm
--- b/src/test/perl/PostgresNode.pm
*************** sub init
*** 447,452 ****
--- 447,453 ----
    print $conf "log_statement = all\n";
    print $conf "log_replication_commands = on\n";
    print $conf "wal_retrieve_retry_interval = '500ms'\n";
+   print $conf "wal_receiver_timeout = '10min'\n";
  
    # If a setting tends to affect whether tests pass or fail, print it after
    # TEMP_CONFIG.  Otherwise, print it before TEMP_CONFIG, thereby permitting

I let it run overnight, and came back to find that it was stuck at

[03:02:15] t/013_partition.pl ................. 19/51

and had been for circa eight hours, where extrapolation from other tests
said it shouldn't take much over half an hour.  Investigation found that
the subscriber was repeatedly failing like this:

2020-09-14 11:05:26.483 EDT [1030506] LOG:  logical replication apply worker for subscription "sub1" has started
2020-09-14 11:05:27.139 EDT [1030506] ERROR:  cache lookup failed for relation 0
2020-09-14 11:05:27.140 EDT [947156] LOG:  background worker "logical replication worker" (PID 1030506) exited with exit code 1
2020-09-14 11:05:27.571 EDT [1030509] LOG:  logical replication apply worker for subscription "sub1" has started
2020-09-14 11:05:28.227 EDT [1030509] ERROR:  cache lookup failed for relation 0
2020-09-14 11:05:28.228 EDT [947156] LOG:  background worker "logical replication worker" (PID 1030509) exited with exit code 1

The publisher's log shows no sign of distress:

2020-09-14 11:06:09.380 EDT [1030619] sub1 LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2020-09-14 11:06:09.446 EDT [1030619] sub1 LOG:  received replication command: IDENTIFY_SYSTEM
2020-09-14 11:06:09.446 EDT [1030619] sub1 LOG:  received replication command: START_REPLICATION SLOT "sub1" LOGICAL 0/163CF08 (proto_version '2', publication_names '"pub1"')
2020-09-14 11:06:09.447 EDT [1030619] sub1 LOG:  starting logical decoding for slot "sub1"
2020-09-14 11:06:09.447 EDT [1030619] sub1 DETAIL:  Streaming transactions committing after 0/163D848, reading WAL from 0/163CF08.
2020-09-14 11:06:09.447 EDT [1030619] sub1 LOG:  logical decoding found consistent point at 0/163CF08
2020-09-14 11:06:09.447 EDT [1030619] sub1 DETAIL:  There are no running transactions.
2020-09-14 11:06:10.468 EDT [1030621] sub1 LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2020-09-14 11:06:10.533 EDT [1030621] sub1 LOG:  received replication command: IDENTIFY_SYSTEM
2020-09-14 11:06:10.534 EDT [1030621] sub1 LOG:  received replication command: START_REPLICATION SLOT "sub1" LOGICAL 0/163CF08 (proto_version '2', publication_names '"pub1"')
2020-09-14 11:06:10.534 EDT [1030621] sub1 LOG:  starting logical decoding for slot "sub1"
2020-09-14 11:06:10.534 EDT [1030621] sub1 DETAIL:  Streaming transactions committing after 0/163D848, reading WAL from 0/163CF08.
2020-09-14 11:06:10.534 EDT [1030621] sub1 LOG:  logical decoding found consistent point at 0/163CF08
2020-09-14 11:06:10.534 EDT [1030621] sub1 DETAIL:  There are no running transactions.

I do not have time today to chase this further, but somebody should.

More generally, this seems like good evidence that we really oughta have a
buildfarm member that's running *all* the tests under CLOBBER_CACHE_ALWAYS
not just the core tests.  That seems impossibly expensive, but I realized
while watching these tests that a ridiculous fraction of the runtime is
being spent in repeated initdb calls.  On my machine, initdb takes about
12 minutes under CCA, so doing it separately for publisher and subscriber
means 24 minutes, which compares not at all favorably to the
circa-half-an-hour total runtime of each of the subscription test scripts.
We're surely not learning anything after the first CCA run of initdb, so
if we could find a way to skip that overhead for later runs, it'd make a
huge difference in the practicality of running these tests under CCA.

I recall having worked on a patch to make the regression tests run
initdb just once, creating a template directory tree, and then "cp -a"
that into place for each test.  I did not finish it, because it wasn't
showing a lot of advantage in a normal test run, but maybe the idea
could be resurrected for CCA and other slow builds.

Another idea is to make CCA a little more dynamic, say allow it to be
suppressed through an environment variable setting, and then use that
to speed up per-test initdbs.

			regards, tom lane

  2. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Neha Sharma <neha.sharma@enterprisedb.com> — 2020-09-14T20:15:52Z

    Hi Tom,

I have tested the subscription test 013_partition.pl with CCA enabled on
HEAD and PG13,
and I am able to reproduce the issue on both the versions.

*Logs:*
[centos@clobber-cache subscription]$ git branch
* REL_13_STABLE
  master
[centos@clobber-cache-db93 subscription]$ tail -f
tmp_check/log/013_partition_subscriber1.log
2020-09-15 08:42:19.763 UTC [27866] LOG:  logical replication apply worker
for subscription "sub1" has started
2020-09-15 08:42:20.395 UTC [27866] ERROR:  cache lookup failed for
relation 0
2020-09-15 08:42:20.436 UTC [26427] LOG:  background worker "logical
replication worker" (PID 27866) exited with exit code 1
2020-09-15 08:42:20.835 UTC [27868] LOG:  logical replication apply worker
for subscription "sub1" has started
2020-09-15 08:42:21.462 UTC [27868] ERROR:  cache lookup failed for
relation 0
2020-09-15 08:42:21.508 UTC [26427] LOG:  background worker "logical
replication worker" (PID 27868) exited with exit code 1
2020-09-15 08:42:21.921 UTC [27870] LOG:  logical replication apply worker
for subscription "sub1" has started
2020-09-15 08:42:22.551 UTC [27870] ERROR:  cache lookup failed for
relation 0


Thanks.
--
Regards,
Neha Sharma


On Mon, Sep 14, 2020 at 8:50 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

> In connection with a nearby thread, I tried to run the subscription
> test suite in a CLOBBER_CACHE_ALWAYS build.  I soon found that I had
> to increase wal_receiver_timeout, but after doing this:
>
> diff --git a/src/test/perl/PostgresNode.pm b/src/test/perl/PostgresNode.pm
> index 1488bff..5fe6810 100644
> *** a/src/test/perl/PostgresNode.pm
> --- b/src/test/perl/PostgresNode.pm
> *************** sub init
> *** 447,452 ****
> --- 447,453 ----
>     print $conf "log_statement = all\n";
>     print $conf "log_replication_commands = on\n";
>     print $conf "wal_retrieve_retry_interval = '500ms'\n";
> +   print $conf "wal_receiver_timeout = '10min'\n";
>
>     # If a setting tends to affect whether tests pass or fail, print it
> after
>     # TEMP_CONFIG.  Otherwise, print it before TEMP_CONFIG, thereby
> permitting
>
> I let it run overnight, and came back to find that it was stuck at
>
> [03:02:15] t/013_partition.pl ................. 19/51
>
> and had been for circa eight hours, where extrapolation from other tests
> said it shouldn't take much over half an hour.  Investigation found that
> the subscriber was repeatedly failing like this:
>
> 2020-09-14 11:05:26.483 EDT [1030506] LOG:  logical replication apply
> worker for subscription "sub1" has started
> 2020-09-14 11:05:27.139 EDT [1030506] ERROR:  cache lookup failed for
> relation 0
> 2020-09-14 11:05:27.140 EDT [947156] LOG:  background worker "logical
> replication worker" (PID 1030506) exited with exit code 1
> 2020-09-14 11:05:27.571 EDT [1030509] LOG:  logical replication apply
> worker for subscription "sub1" has started
> 2020-09-14 11:05:28.227 EDT [1030509] ERROR:  cache lookup failed for
> relation 0
> 2020-09-14 11:05:28.228 EDT [947156] LOG:  background worker "logical
> replication worker" (PID 1030509) exited with exit code 1
>
> The publisher's log shows no sign of distress:
>
> 2020-09-14 11:06:09.380 EDT [1030619] sub1 LOG:  statement: SELECT
> pg_catalog.set_config('search_path', '', false);
> 2020-09-14 11:06:09.446 EDT [1030619] sub1 LOG:  received replication
> command: IDENTIFY_SYSTEM
> 2020-09-14 11:06:09.446 EDT [1030619] sub1 LOG:  received replication
> command: START_REPLICATION SLOT "sub1" LOGICAL 0/163CF08 (proto_version
> '2', publication_names '"pub1"')
> 2020-09-14 11:06:09.447 EDT [1030619] sub1 LOG:  starting logical decoding
> for slot "sub1"
> 2020-09-14 11:06:09.447 EDT [1030619] sub1 DETAIL:  Streaming transactions
> committing after 0/163D848, reading WAL from 0/163CF08.
> 2020-09-14 11:06:09.447 EDT [1030619] sub1 LOG:  logical decoding found
> consistent point at 0/163CF08
> 2020-09-14 11:06:09.447 EDT [1030619] sub1 DETAIL:  There are no running
> transactions.
> 2020-09-14 11:06:10.468 EDT [1030621] sub1 LOG:  statement: SELECT
> pg_catalog.set_config('search_path', '', false);
> 2020-09-14 11:06:10.533 EDT [1030621] sub1 LOG:  received replication
> command: IDENTIFY_SYSTEM
> 2020-09-14 11:06:10.534 EDT [1030621] sub1 LOG:  received replication
> command: START_REPLICATION SLOT "sub1" LOGICAL 0/163CF08 (proto_version
> '2', publication_names '"pub1"')
> 2020-09-14 11:06:10.534 EDT [1030621] sub1 LOG:  starting logical decoding
> for slot "sub1"
> 2020-09-14 11:06:10.534 EDT [1030621] sub1 DETAIL:  Streaming transactions
> committing after 0/163D848, reading WAL from 0/163CF08.
> 2020-09-14 11:06:10.534 EDT [1030621] sub1 LOG:  logical decoding found
> consistent point at 0/163CF08
> 2020-09-14 11:06:10.534 EDT [1030621] sub1 DETAIL:  There are no running
> transactions.
>
> I do not have time today to chase this further, but somebody should.
>
> More generally, this seems like good evidence that we really oughta have a
> buildfarm member that's running *all* the tests under CLOBBER_CACHE_ALWAYS
> not just the core tests.  That seems impossibly expensive, but I realized
> while watching these tests that a ridiculous fraction of the runtime is
> being spent in repeated initdb calls.  On my machine, initdb takes about
> 12 minutes under CCA, so doing it separately for publisher and subscriber
> means 24 minutes, which compares not at all favorably to the
> circa-half-an-hour total runtime of each of the subscription test scripts.
> We're surely not learning anything after the first CCA run of initdb, so
> if we could find a way to skip that overhead for later runs, it'd make a
> huge difference in the practicality of running these tests under CCA.
>
> I recall having worked on a patch to make the regression tests run
> initdb just once, creating a template directory tree, and then "cp -a"
> that into place for each test.  I did not finish it, because it wasn't
> showing a lot of advantage in a normal test run, but maybe the idea
> could be resurrected for CCA and other slow builds.
>
> Another idea is to make CCA a little more dynamic, say allow it to be
> suppressed through an environment variable setting, and then use that
> to speed up per-test initdbs.
>
>                         regards, tom lane
>
>
>

  3. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-09-15T19:46:18Z

    I wrote:
> [ $subject ]

I found some time to trace this down, and what it turns out to be is
that apply_handle_truncate() is making use of a LogicalRepRelMapEntry's
localreloid field without any consideration for the possibility that
that's been set to zero as a result of a cache flush.  The visible
symptom of "cache lookup failed for relation 0" comes from trying
to invoke find_all_inheritors with a zero OID.

Now, study of apply_handle_truncate doesn't immediately reveal where
a cache flush could have occurred, but I realized that it's actually
possible that the LogicalRepRelMapEntry is *already* marked invalid
when logicalrep_rel_open() returns!  That's because for some reason
it does GetSubscriptionRelState last, after it's already marked the
entry valid, and that function does plenty o' catalog accesses.

It's not really clear to me why setting localreloid to zero is a sane
way to represent "this entry needs to be revalidated".  I think a
separate flag would be more appropriate.  Once we have lock on the
target relation, it seems to me that no interesting changes should
be possible as long as we have lock; so there's no very good reason
to destroy useful state to remind ourselves that we should recheck
it next time.

			regards, tom lane

  4. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-09-15T21:30:15Z

    I wrote:
> It's not really clear to me why setting localreloid to zero is a sane
> way to represent "this entry needs to be revalidated".  I think a
> separate flag would be more appropriate.  Once we have lock on the
> target relation, it seems to me that no interesting changes should
> be possible as long as we have lock; so there's no very good reason
> to destroy useful state to remind ourselves that we should recheck
> it next time.

Here's a patch that changes that, and also cleans up some sloppy
thinking about how to re-acquire lock on the replication target
relation.  (Just because the OID was valid last you heard does
not mean that table_open is guaranteed to succeed.)

With this, we get through 013_partition.pl under CCA.  I plan to
try to run all of subscription/ and recovery/ before concluding
there's nothing else to fix, though.

			regards, tom lane

  5. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-09-16T00:16:26Z

    I wrote:
> With this, we get through 013_partition.pl under CCA.  I plan to
> try to run all of subscription/ and recovery/ before concluding
> there's nothing else to fix, though.

Looks like the rest passes.  FTR, it was possible to get through
subscription/ in about 2 hours on my workstation, and recovery/ in about
30 minutes, after hacking things so that initdb used a non-CCA backend.
So that's definitely a promising thing to look at if anyone wants
to try to do this on a regular basis.

Aside from increasing wal_receiver_timeout as previously mentioned,
I found I had to set a higher pg_ctl start timeout using PGCTLTIMEOUT
in order to get through the recovery tests.

			regards, tom lane

  6. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Amit Kapila <amit.kapila16@gmail.com> — 2020-09-16T03:49:36Z

    On Wed, Sep 16, 2020 at 1:16 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> I wrote:
> It's not really clear to me why setting localreloid to zero is a sane
> way to represent "this entry needs to be revalidated".  I think a
> separate flag would be more appropriate.  Once we have lock on the
> target relation, it seems to me that no interesting changes should
> be possible as long as we have lock; so there's no very good reason
> to destroy useful state to remind ourselves that we should recheck
> it next time.
>

So, can we assume that the current code can only cause the problem in
CCA builds bot not in any practical scenario because after having a
lock on relation probably there shouldn't be any invalidation which
leads to this problem?

-- 
With Regards,
Amit Kapila.

  7. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-09-16T04:11:02Z

    Amit Kapila <amit.kapila16@gmail.com> writes:
> So, can we assume that the current code can only cause the problem in
> CCA builds bot not in any practical scenario because after having a
> lock on relation probably there shouldn't be any invalidation which
> leads to this problem?

No.  The reason we expend so much time and effort on CCA testing is
that cache flushes are unpredictable, and they can happen even when
you have a lock on the object(s) in question.  In particular, the
easiest real-world case that could cause the described problem is an
sinval queue overrun that we detect during the GetSubscriptionRelState
call at the bottom of logicalrep_rel_open.  In that case we'll
come back to the caller with the LogicalRepRelMapEntry marked as
already needing revalidation, because the cache inval callback
will have marked *all* of them that way.  That's actually a harmless
condition, because we have lock on the rel so nothing really
changed ... but if we blew away localreloid and the caller needs
to use that, kaboom.

We could imagine marking the entry valid at the very bottom of
logicalrep_rel_open, but that just moves the problem somewhere else.
Any caller that does *any* catalog access while holding open a
LogicalRepRelMapEntry would not be able to rely on its localreloid
staying valid.  That's a recipe for irreproducible bugs, and it's
unnecessary.  In practice the entry is good as long as
we continue to hold a lock on the local relation.  So we should
mark LogicalRepRelMapEntries as potentially-needing-revalidation
in a way that doesn't interfere with active users of the entry.

In short: the value of CCA testing is to model sinval overruns
happening at any point where they could happen.  The real-world
odds of one happening at any given instant are low, but they're
never zero.

			regards, tom lane

  8. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Amit Kapila <amit.kapila16@gmail.com> — 2020-09-16T05:53:16Z

    On Wed, Sep 16, 2020 at 9:41 AM Tom Lane <tgl@sss.pgh.pa.us> wrote:
>
> Amit Kapila <amit.kapila16@gmail.com> writes:
> > So, can we assume that the current code can only cause the problem in
> > CCA builds bot not in any practical scenario because after having a
> > lock on relation probably there shouldn't be any invalidation which
> > leads to this problem?
>
>
> In short: the value of CCA testing is to model sinval overruns
> happening at any point where they could happen.  The real-world
> odds of one happening at any given instant are low, but they're
> never zero.
>

Thanks for the explanation. I have read your patch and it looks good to me.

-- 
With Regards,
Amit Kapila.

  9. Re: Subscription test 013_partition.pl fails under CLOBBER_CACHE_ALWAYS

    Tom Lane <tgl@sss.pgh.pa.us> — 2020-09-16T16:09:24Z

    Amit Kapila <amit.kapila16@gmail.com> writes:
> Thanks for the explanation. I have read your patch and it looks good to me.

Pushed, thanks for checking the patch.

			regards, tom lane