Re: [HACKERS] logical decoding of two-phase transactions - Mailing list pgsql-hackers

On Mon, Nov 30, 2020 at 2:36 PM Ajin Cherian <itsajin@gmail.com> wrote:
>
> On Sun, Nov 29, 2020 at 1:07 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> > Then once you found which existing test covers
> > that, you can try to generate prepared transaction behavior as
> > mentioned above.
>
> I was able to find out the test case that exercises that code, it is
> the ondisk_startup spec in test_decoding. Using that, I was able to
> create the problem with the following setup:
> Using 4 sessions (this could be optimized to 3, but just sharing what
> I've tested):
>
> s1(session 1):
> begin;
> postgres=# begin;
> BEGIN
> postgres=*# SELECT pg_current_xact_id();
>  pg_current_xact_id
> --------------------
>                 546
> (1 row)
> --------------------the above commands leave a transaction running
> s2:
> CREATE TABLE do_write(id serial primary key);
> SELECT 'init' FROM
> pg_create_logical_replication_slot('isolation_slot', 'test_decoding');
>
> ---------------------this will hang because of 546 txn is pending
>
> s3:
> postgres=# begin;
> BEGIN
> postgres=*# SELECT pg_current_xact_id();
>  pg_current_xact_id
> --------------------
>                 547
> (1 row)
> -------------------------------- leave another txn pending---
>
> s1:
> postgres=*# ALTER TABLE do_write ADD COLUMN addedbys2 int;
> ALTER TABLE
> postgres=*# commit;
> ------------------------------commit the first txn; this will cause
> state to move to SNAPBUILD_FULL_SNAPSHOT state
> 2020-11-30 03:31:07.354 EST [16312] LOG:  logical decoding found
> initial consistent point at 0/1730A18
> 2020-11-30 03:31:07.354 EST [16312] DETAIL:  Waiting for transactions
> (approximately 1) older than 553 to end.
>
>
> s4:
> postgres=# begin;
> BEGIN
> postgres=*# INSERT INTO do_write DEFAULT VALUES;
> INSERT 0 1
> postgres=*# prepare transaction 'test1';
> PREPARE TRANSACTION
> -------------- leave this transaction prepared
>
> s3:
> postgres=*# commit;
> COMMIT
> ----------------- this will cause s2 call to return and a consistent
> point has been reached.
> 2020-11-30 03:31:34.200 EST [16312] LOG:  logical decoding found
> consistent point at 0/1730D58
>
> s4:
> commit prepared 'test1';
>
> s2:
> postgres=# SELECT * FROM pg_logical_slot_get_changes('isolation_slot',
> NULL, NULL, 'two-phase-commit', '1', 'include-xids', '0',
> 'skip-empty-xacts', '1');
>     lsn    | xid |          data
> -----------+-----+-------------------------
>  0/1730FC8 | 553 | COMMIT PREPARED 'test1'
> (1 row)
>
> In pg_logical_slot_get_changes() we see only the Commit Prepared but
> no insert and no prepare command. I debugged this and I see that in
> DecodePrepare, the
> prepare is skipped because the prepare lsn is prior to the
> start_decoding_at point and is skipped in SnapBuildXactNeedsSkip.
>

So what caused it to skip due to start_decoding_at? Because the commit
where the snapshot became consistent is after Prepare. Does it happen
due to the below code in SnapBuildFindSnapshot() where we bump
start_decoding_at.

{
...
if (running->oldestRunningXid == running->nextXid)
{
if (builder->start_decoding_at == InvalidXLogRecPtr ||
builder->start_decoding_at <= lsn)
/* can decode everything after this */
builder->start_decoding_at = lsn + 1;

>  So,
> the reason for skipping
> the PREPARE is similar to the reason why it would have been skipped on
> a restart after a previous decode run.
>
> One possible fix would be similar to what you suggested, in
> DecodePrepare , add the check DecodingContextReady(ctx), which if
> false would indicate that the
> PREPARE was prior to a consistent snapshot and if so, set a flag value
> in txn accordingly
>

Sure, but you can see in your example above it got skipped due to
start_decoding_at not due to DecodingContextReady. So, the problem as
mentioned by me previously was how we distinguish those cases because
it can skip due to start_decoding_at during restart as well when we
would have already sent the prepare to the subscriber.

One idea could be that the subscriber skips the transaction if it sees
the transaction is already prepared. We already skip changes in apply
worker (subscriber) if they are performed via tablesync worker, see
should_apply_changes_for_rel. This will be a different thing but I am
trying to indicate that something similar is already done in
subscriber. I am not sure if we can detect this in publisher, if so,
that would be also worth considering and might be better.

Thoughts?

-- 
With Regards,
Amit Kapila.