Thread: Conflict detection and logging in logical replication

Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

21 June 2024, 07:47:20

Hi hackers,
Cc people involved in the original thread[1].

I am starting a new thread to share and discuss the implementation of
conflict detection and logging in logical replication, as well as the
collection of statistics related to these conflicts.

In the original conflict resolution thread[1], we have decided to
split this work into multiple patches to facilitate incremental progress
towards supporting conflict resolution in logical replication. This phased
approach will allow us to address simpler tasks first. The overall work
plan involves: 1. conflict detection (detect and log conflicts like
'insert_exists', 'update_differ', 'update_missing', and 'delete_missing')
2. implement simple built-in resolution strategies like
'apply(remote_apply)' and 'skip(keep_local)'. 3. monitor capability for
conflicts and resolutions in statistics or history table.

Following the feedback received from PGconf.dev and discussions in the
conflict resolution thread, features 1 and 3 are important independently.
So, we start a separate thread for them.

Here are the basic designs for the detection and statistics:

- The detail of the conflict detection

We add a new parameter detect_conflict for CREATE and ALTER subscription
commands. This new parameter will decide if subscription will go for
confict detection. By default, conflict detection will be off for a
subscription.

When conflict detection is enabled, additional logging is triggered in the
following conflict scenarios:
insert_exists: Inserting a row that violates a NOT DEFERRABLE unique constraint.
update_differ: updating a row that was previously modified by another origin.
update_missing: The tuple to be updated is missing.
delete_missing: The tuple to be deleted is missing.

For insert_exists conflict, the log can include origin and commit
timestamp details of the conflicting key with track_commit_timestamp
enabled. And update_differ conflict can only be detected when
track_commit_timestamp is enabled.

Regarding insert_exists conflicts, the current design is to pass
noDupErr=true in ExecInsertIndexTuples() to prevent immediate error
handling on duplicate key violation. After calling
ExecInsertIndexTuples(), if there was any potential conflict in the
unique indexes, we report an ERROR for the insert_exists conflict along
with additional information (origin, committs, key value) for the
conflicting row. Another way for this is to conduct a pre-check for
duplicate key violation before applying the INSERT operation, but this
could introduce overhead for each INSERT even in the absence of conflicts.
We welcome any alternative viewpoints on this matter.

- The detail of statistics collection

We add columns(insert_exists_count, update_differ_count,
update_missing_count, delete_missing_count) in view
pg_stat_subscription_workers to shows information about the conflict which
occur during the application of logical replication changes.

The conflicts will be tracked when track_conflict option of the
subscription is enabled. Additionally, update_differ can be detected only
when track_commit_timestamp is enabled.

The patches for above features are attached.
Suggestions and comments are highly appreciated.

[1] https://www.postgresql.org/message-id/CAA4eK1LgPyzPr_Vrvvr4syrde4hyT%3DQQnGjdRUNP-tz3eYa%3DGQ%40mail.gmail.com

Best Regards,
Hou Zhijie

Attachment

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

24 June 2024, 02:09:27

On Friday, June 21, 2024 3:47 PM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com> wrote:
>
> - The detail of the conflict detection
>
> We add a new parameter detect_conflict for CREATE and ALTER subscription
> commands. This new parameter will decide if subscription will go for
> confict detection. By default, conflict detection will be off for a
> subscription.
>
> When conflict detection is enabled, additional logging is triggered in the
> following conflict scenarios:
> insert_exists: Inserting a row that violates a NOT DEFERRABLE unique
> constraint.
> update_differ: updating a row that was previously modified by another origin.
> update_missing: The tuple to be updated is missing.
> delete_missing: The tuple to be deleted is missing.
>
> For insert_exists conflict, the log can include origin and commit
> timestamp details of the conflicting key with track_commit_timestamp
> enabled. And update_differ conflict can only be detected when
> track_commit_timestamp is enabled.
>
> Regarding insert_exists conflicts, the current design is to pass
> noDupErr=true in ExecInsertIndexTuples() to prevent immediate error
> handling on duplicate key violation. After calling
> ExecInsertIndexTuples(), if there was any potential conflict in the
> unique indexes, we report an ERROR for the insert_exists conflict along
> with additional information (origin, committs, key value) for the
> conflicting row. Another way for this is to conduct a pre-check for
> duplicate key violation before applying the INSERT operation, but this
> could introduce overhead for each INSERT even in the absence of conflicts.
> We welcome any alternative viewpoints on this matter.

When testing the patch, I noticed a bug that when reporting the conflict
after calling ExecInsertIndexTuples(), we might find the tuple that we
just inserted and report it.(we should only report conflict if there are
other conflict tuples which are not inserted by us) Here is a new patch
which fixed this and fixed a compile warning reported by CFbot.

Best Regards,
Hou zj

On Monday, June 24, 2024 8:35 PM Nisha Moond <nisha.moond412@gmail.com> wrote:
> 
> On Mon, Jun 24, 2024 at 7:39 AM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > When testing the patch, I noticed a bug that when reporting the
> > conflict after calling ExecInsertIndexTuples(), we might find the
> > tuple that we just inserted and report it.(we should only report
> > conflict if there are other conflict tuples which are not inserted by
> > us) Here is a new patch which fixed this and fixed a compile warning
> reported by CFbot.
> >
> Thank you for the patch!
> A review comment: The patch does not detect 'update_differ' conflicts when
> the Publisher has a non-partitioned table and the Subscriber has a partitioned
> version.

Thanks for reporting the issue !

Here is the new version patch set which fixed this issue. I also fixed
some typos and improved the doc in logical replication conflict based
on the comments from Shveta[1].

[1] https://www.postgresql.org/message-id/CAJpy0uABSf15E%2BbMDBRCpbFYo0dh4N%3DEtpv%2BSNw6RMy8ohyrcQ%40mail.gmail.com

Best Regards,
Hou zj

Attachment

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

03 July 2024, 03:00:50

On Wednesday, June 26, 2024 10:58 AM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com> wrote:
>

Hi,

As suggested by Sawada-san in another thread[1].

I am attaching the V4 patch set which tracks the delete_differ
conflict in logical replication.

delete_differ means that the replicated DELETE is deleting a row
that was modified by a different origin.

[1] https://www.postgresql.org/message-id/CAD21AoDzo8ck57nvRVFWOCsjWBCjQMzqTFLY4cCeFeQZ3V_oQg%40mail.gmail.com

Best regards,
Hou zj

On Thursday, July 11, 2024 1:03 PM shveta malik <shveta.malik@gmail.com> wrote:

Hi,

Thanks for the comments!

> 
> I have one concern about how we deal with conflicts. As for insert_exists, we
> keep on erroring out while raising conflict, until it is manually resolved:
> ERROR:  conflict insert_exists detected
> 
> But for other cases, we just log conflict and either skip or apply the operation. I
> LOG:  conflict update_differ detected
> DETAIL:  Updating a row that was modified by a different origin
> 
> I know that it is no different than HEAD. But now since we are logging conflicts
> explicitly, we should call out default behavior on each conflict. I see some
> incomplete and scattered info in '31.5.
> Conflicts' section saying that:
>  "When replicating UPDATE or DELETE operations, missing data will not
> produce a conflict and such operations will simply be skipped."
> (lets say it as pt a)
> 
> Also some more info in a later section saying (pt b):
> :A conflict will produce an error and will stop the replication; it must be resolved
> manually by the user."
> 
> My suggestions:
> 1) in point a above, shall we have:
> missing data or differing data (i.e. somehow reword to accommodate
> update_differ and delete_differ cases)

I am not sure if rewording existing words is better. I feel adding a link to
let user refer to the detect_conflict section for the all the
conflicts is sufficient, so did like that.

>
> 2)
> monitoring.sgml: Below are my suggestions, please change if you feel apt.
> 
> 2a) insert_exists_count : Number of times inserting a row that violates a NOT
> DEFERRABLE unique constraint while applying changes. Suggestion: Number of
> times a row insertion violated a NOT DEFERRABLE unique constraint while
> applying changes.
> 
> 2b) update_differ_count : Number of times updating a row that was previously
> modified by another source while applying changes. Suggestion: Number of times
> update was performed on a row that was previously modified by another source
> while applying changes.
> 
> 2c) delete_differ_count: Number of times deleting a row that was previously
> modified by another source while applying changes. Suggestion: Number of times
> delete was performed on a row that was previously modified by another source
> while applying changes.

I am a bit unsure which one is better, so I didn't change in this version.

> 
> 5)
> conflict.h:CONFLICT_NUM_TYPES
> 
> --Shall the macro be CONFLICT_TYPES_NUM  instead?

I think the current style followed existing ones(e.g. IOOP_NUM_TYPES,
BACKEND_NUM_TYPES, IOOBJECT_NUM_TYPES ...), so I didn't change this.

Attach the V5 patch set which changed the following:
1. addressed shveta's comments which are not mentioned above.
2. support update_exists conflict which indicates
that the updated value of a row violates the unique constraint.

Best Regards,
Hou zj

On Monday, July 22, 2024 5:03 PM shveta malik <shveta.malik@gmail.com> wrote:
> 
> On Fri, Jul 19, 2024 at 2:06 PM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > On Thu, Jul 18, 2024 at 7:52 AM Zhijie Hou (Fujitsu)
> > <houzj.fnst@fujitsu.com> wrote:
> > >
> > > Attach the V5 patch set which changed the following.
> >
> 
> Please find last batch of comments on v5:

Thanks Shveta and Nisha for giving comments!

> 
> 
> 2)
> 013_partition.pl: Since we have added update_differ testcase here, we shall
> add delete_differ as well. 

I didn't add tests for delete_differ in partition test, because I think the main
codes and functionality of delete_differ have been tested in 030_origin.pl.
The test for update_differ is needed because the patch adds new codes in
partition code path to report this conflict.

Here is the V6 patch set which addressed Shveta and Nisha's comments
in [1][2][3][4].

[1] https://www.postgresql.org/message-id/CAJpy0uDWdw2W-S8boFU0KOcZjw0%2BsFFgLrHYrr1TROtrcTPZMg%40mail.gmail.com
[2] https://www.postgresql.org/message-id/CAJpy0uDGJXdVCGoaRHP-5G0pL0zhuZaRJSqxOxs%3DCNsSwc%2BSJQ%40mail.gmail.com
[3] https://www.postgresql.org/message-id/CAJpy0uC%2B1puapWdOnAMSS%3DQUp_1jj3GfAeivE0JRWbpqrUy%3Dug%40mail.gmail.com
[4]
https://www.postgresql.org/message-id/CABdArM6%2BN1Xy_%2BtK%2Bu-H%3DsCB%2B92rAUh8qH6GDsB%2B1naKzgGKzQ%40mail.gmail.com

Best Regards,
Hou zj

On Friday, July 26, 2024 7:34 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Thu, Jul 25, 2024 at 4:12 PM Amit Kapila <amit.kapila16@gmail.com>
> wrote:
> > > 
> A few more comments:

Thanks for the comments.

> 1.
> For duplicate key, the patch reports conflict as following:
> ERROR:  conflict insert_exists detected on relation "public.t1"
> 2024-07-26 11:06:34.570 IST [27800] DETAIL:  Key (c1)=(1) already exists in
> unique index "t1_pkey", which was modified by origin 1 in transaction 770 at
> 2024-07-26 09:16:47.79805+05:30.
> 2024-07-26 11:06:34.570 IST [27800] CONTEXT:  processing remote data for
> replication origin "pg_16387" during message type "INSERT" for replication
> target relation "public.t1" in transaction 742, finished at 0/151A108
> 
> In detail, it is better to display the origin name instead of the origin id. This will
> be similar to what we do in CONTEXT information.

Agreed. Before modifying this, I'd like to confirm the message style in the
cases where origin id may not have a corresponding origin name (e.g., if the
data was modified locally (id = 0), or if the origin that modified the data has
been dropped). I thought of two styles:

1)
- for local change: "xxx was modified by a different origin \"(local)\" in transaction 123 at 2024.."
- for dropped origin: "xxx was modified by a different origin \"(unknown)\" in transaction 123 at 2024.."

One issue for this style is that user may create an origin with the same name
here (e.g. "(local)" and "(unknown)").

2) 
- for local change: "xxx was modified locally in transaction 123 at 2024.."
- for dropped origin: "xxx was modified by an unknown different origin 1234 in transaction 123 at 2024.."

This style slightly modifies the message format. I personally feel 2) maybe
better but am OK for other options as well.

What do you think ?

Here is the V7 patch set that addressed all the comments so far[1][2][3].
The subscription option part is splitted into the separate patch 0002 and
we will decide whether to drop this patch after finishing the perf tests.
Note that I didn't display the tuple value in the message as the discussion
is still ongoing[4].

[1] https://www.postgresql.org/message-id/CAJpy0uDhCnzvNHVYwse%3DKxmOB%3DqtXr6twnDP9xqdzT-oU0OWEQ%40mail.gmail.com
[2] https://www.postgresql.org/message-id/CAA4eK1%2BCJXKK34zJdEJZf2Mpn5QyMyaZiPDSNS6%3Dkvewr0-pdg%40mail.gmail.com
[3] https://www.postgresql.org/message-id/CAA4eK1Lmu%3DoVySfGjxEUykCT3FPnL1YFDHKr1ZMwFy7WUgfc6g%40mail.gmail.com
[4] https://www.postgresql.org/message-id/CAA4eK1%2BaK4MLxbfLtp%3DEV5bpvJozKhxGDRS6T9q8sz_s%2BLK3vw%40mail.gmail.com

Best Regards,
Hou zj

On Tuesday, July 30, 2024 5:06 PM shveta malik <shveta.malik@gmail.com> wrote:
> 
> On Mon, Jul 29, 2024 at 11:44 AM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > Here is the V7 patch set that addressed all the comments so far[1][2][3].
> 
> Thanks for the patch, few comments:

Thanks for the comments !

> 
> 2)
> apply_handle_delete_internal()
> 
> --Do we need to check "(!edata->mtstate || edata->mtstate->operation !=
> CMD_UPDATE)" in the else part as well? Can there be a scenario where during
> update flow, it is trying to delete from a partition and comes here, but till then
> that row is deleted already and we end up raising 'delete_missing' additionally
> instead of 'update_missing'
> alone?

I think this shouldn't happen because the row to be deleted should have been
locked before entering the apply_handle_delete_internal(). Actually, calling
apply_handle_delete_internal() for cross-partition update is a big buggy because the
row to be deleted has already been found in apply_handle_tuple_routing(), so we
could have avoid scanning the tuple again. I have posted another patch to fix
this issue in thread[1].

Here is the V8 patch set. It includes the following changes:

* Addressed the comments from Shveta.
* Reported the origin name in the DETAIL instead of the origin id.
* fixed the issue Dilip pointed[2].
* fixed one old issue[3] Nisha pointed that I missed to fix in previous version.
* Improved the document a bit.

[1] https://www.postgresql.org/message-id/CAA4eK1JsNPzFE8dgFOm-Tfk_CDZyg1R3zuuQWkUnef-N-vTkoA%40mail.gmail.com
[2] https://www.postgresql.org/message-id/CAFiTN-tYdN63U%3Dd8V8rBfRtFmhZ%3DQQX7jEmj1cdWMe_NM%2B7%3DTQ%40mail.gmail.com
[3]
https://www.postgresql.org/message-id/CABdArM6%2BN1Xy_%2BtK%2Bu-H%3DsCB%2B92rAUh8qH6GDsB%2B1naKzgGKzQ%40mail.gmail.com

Best Regards,
Hou zj

On Wednesday, July 31, 2024 6:53 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Wed, Jul 31, 2024 at 7:40 AM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
> wrote:
> >
> > Here is the V8 patch set. It includes the following changes:
> >
> 
> A few more comments:
> 1. I think in FindConflictTuple() the patch is locking the tuple so that after
> finding a conflict if there is a concurrent delete, it can retry to find the tuple. If
> there is no concurrent delete then we can successfully report the conflict. Is
> that correct? If so, it is better to explain this somewhere in the comments.
> 
> 2.
> * Note that this doesn't lock the values in any way, so it's
>  * possible that a conflicting tuple is inserted immediately
>  * after this returns.  But this can be used for a pre-check
>  * before insertion.
> ..
> ExecCheckIndexConstraints()
> 
> These comments indicate that this function can be used before inserting the
> tuple, however, this patch uses it after inserting the tuple as well. So, I think the
> comments should be updated accordingly.
> 
> 3.
>  * For unique indexes, we usually don't want to add info to the IndexInfo for
>  * checking uniqueness, since the B-Tree AM handles that directly.  However,
>  * in the case of speculative insertion, additional support is required.
> ...
> BuildSpeculativeIndexInfo(){...}
> 
> This additional support is now required even for logical replication to detect
> conflicts. So the comments atop this function should reflect the same.

Thanks for the comments.

Here is the V9 patch set which addressed above and Shveta's comments.

Best Regards,
Hou zj

Attachment

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

01 August 2024, 06:09:41

On Thursday, August 1, 2024 11:40 AM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
> Here is the V9 patch set which addressed above and Shveta's comments.
> 

The patch conflict with a recent commit a67da49, so here is rebased V10 patch set. 

Thanks to the commit a67da49, I have removed the special check for
cross-partition update in apply_handle_delete_internal() because this function
will not be called in cross-update anymore.

Best Regards,
Hou zj

On Thu, Aug 1, 2024 at 5:23 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Thu, Aug 1, 2024 at 2:26 PM Hayato Kuroda (Fujitsu)
> <kuroda.hayato@fujitsu.com> wrote:
> >
> > 04. general
> >
> > According to the documentation [1], there is another constraint "exclude", which
> > can cause another type of conflict. But this pattern cannot be logged in detail.
> >
>
> As per docs, "exclusion constraints can specify constraints that are
> more general than simple equality", so I don't think it satisfies the
> kind of conflicts we are trying to LOG and then in the future patch
> allows automatic resolution for the same. For example, when we have
> last_update_wins strategy, we will replace the rows with remote rows
> when the key column values match which shouldn't be true in general
> for exclusion constraints. Similarly, we don't want to consider other
> constraint violations like CHECK to consider as conflicts. We can
> always extend the basic functionality for more conflicts if required
> but let's go with reporting straight-forward stuff first.
>

It is better to document that exclusion constraints won't be
supported. We can even write a comment in the code and or commit
message that we can extend it in the future.

*
+ * Return true if the commit timestamp data was found, false otherwise.
+ */
+bool
+GetTupleCommitTs(TupleTableSlot *localslot, TransactionId *xmin,
+ RepOriginId *localorigin, TimestampTz *localts)

This API returns both xmin and commit timestamp, so wouldn't it be
better to name it as GetTupleTransactionInfo or something like that?

I have made several changes in the attached top-up patch. These
include changes in the comments, docs, function names, etc.

--
With Regards,
Amit Kapila.

Attachment

v10_amit_diff.patch.txt

Re: Conflict detection and logging in logical replication

From

Nisha Moond

Date:

02 August 2024, 12:58:13

Performance tests done on the v8-0001 and v8-0002 patches, available at [1].

The purpose of the performance tests is to measure the impact on
logical replication with track_commit_timestamp enabled, as this
involves fetching the commit_ts data to determine
delete_differ/update_differ conflicts.

Fortunately, we did not see any noticeable overhead from the new
commit_ts fetch and comparison logic. The only notable impact is
potential overhead from logging conflicts if they occur frequently.
Therefore, enabling conflict detection by default seems feasible, and
introducing a new detect_conflict option may not be necessary.

Please refer to the following for detailed test results:

For all the tests, created two server nodes, one publisher and one as
subscriber. Both the nodes are configured with below settings -
  wal_level = logical
  shared_buffers = 40GB
  max_worker_processes = 32
  max_parallel_maintenance_workers = 24
  max_parallel_workers = 32
  synchronous_commit = off
  checkpoint_timeout = 1d
  max_wal_size = 24GB
  min_wal_size = 15GB
  autovacuum = off
~~~~

Test 1: create conflicts on Sub using pgbench.
----------------------------------------------------------------
Setup:
 - Both publisher and subscriber have pgbench tables created as-
      pgbench -p $node1_port postgres -qis 1
 - At Sub, a subscription created for all the changes from Pub node.

Test Run:
 - To test, ran pgbench for 15 minutes on both nodes simultaneously,
which led to concurrent updates and update_differ conflicts on the
Subscriber node.
 Command used to run pgbench on both nodes-
        ./pgbench postgres -p 8833 -c 10 -j 3 -T 300 -P 20

Results:
For each case, note the “tps” and total time taken by the apply-worker
on Sub to apply the changes coming from Pub.

Case1: track_commit_timestamp = off, detect_conflict = off
    Pub-tps = 9139.556405
    Sub-tps = 8456.787967
    Time of replicating all the changes: 19min 28s
Case 2 : track_commit_timestamp = on, detect_conflict = on
    Pub-tps = 8833.016548
    Sub-tps = 8389.763739
    Time of replicating all the changes: 20min 20s
Case3: track_commit_timestamp = on, detect_conflict = off
    Pub-tps = 8886.101726
    Sub-tps = 8374.508017
    Time of replicating all the changes: 19min 35s
Case 4: track_commit_timestamp = off, detect_conflict = on
    Pub-tps = 8981.924596
    Sub-tps = 8411.120808
    Time of replicating all the changes: 19min 27s

**The difference of TPS between each case is small. While I can see a
slight increase of the replication time (about 5%), when enabling both
track_commit_timestamp and detect_conflict.

Test2: create conflict using a manual script
----------------------------------------------------------------
 - To measure the precise time taken by the apply-worker in all cases,
create a test with a table having 10 million rows.
 - To record the total time taken by the apply-worker, dump the
current time in the logfile for apply_handle_begin() and
apply_handle_commit().

Setup:
Pub : has a table ‘perf’ with 10 million rows.
Sub : has the same table ‘perf’ with its own 10 million rows (inserted
by 1000 different transactions). This table is subscribed for all
changes from Pub.

Test Run:
At Pub: run UPDATE on the table ‘perf’ to update all its rows in a
single transaction. (this will lead to update_differ conflict for all
rows on Sub when enabled).
At Sub: record the time(from log file) taken by the apply-worker to
apply all updates coming from Pub.

Results:
Below table shows the total time taken by the apply-worker
(apply_handle_commit Time - apply_handle_begin Time ).
(Two test runs for each of the four cases)

Case1: track_commit_timestamp = off, detect_conflict = off
    Run1 - 2min 42sec 579ms
    Run2 - 2min 41sec 75ms
Case 2 : track_commit_timestamp = on, detect_conflict = on
    Run1 - 6min 11sec 602ms
    Run2 - 6min 25sec 179ms
Case3: track_commit_timestamp = on, detect_conflict = off
    Run1 - 2min 34sec 223ms
    Run2 - 2min 33sec 482ms
Case 4: track_commit_timestamp = off, detect_conflict = on
    Run1 - 2min 35sec 276ms
    Run2 - 2min 38sec 745ms

** In the case-2 when both track_commit_timestamp and detect_conflict
are enabled, the time taken by the apply-worker is ~140% higher.

Test3: Case when no conflict is detected.
----------------------------------------------------------------
To measure the time taken by the apply-worker when there is no
conflict detected. This test is to confirm if the time overhead in
Test1-Case2 is due to the new function GetTupleCommitTs() which
fetches the origin and timestamp information for each row in the table
before applying the update.

Setup:
 - The Publisher and Subscriber both have an empty table to start with.
 - At Sub, the table is subscribed for all changes from Pub.
 - At Pub: Insert 10 million rows and the same will be replicated to
the Sub table as well.

Test Run:
At Pub: run an UPDATE on the table to update all rows in a single
transaction. (This will NOT hit the update_differ on Sub because now
all the tuples have the Pub’s origin).

Results:
Case1: track_commit_timestamp = off, detect_conflict = off
    Run1 - 2min 39sec 261ms
    Run2 - 2min 30sec 95ms
Case 2 : track_commit_timestamp = on, detect_conflict = on
    Run1 - 2min 38sec 985ms
    Run2 - 2min 46sec 624ms
Case3: track_commit_timestamp = on, detect_conflict = off
    Run1 - 2min 59sec 887ms
    Run2 - 2min 34sec 336ms
Case 4: track_commit_timestamp = off, detect_conflict = on
    Run1 - 2min 33sec 477min
    Run2 - 2min 37sec 677ms

Test Summary -
-- The duration for case-2 was reduced to 2-3 minutes, matching the
times of the other cases.
-- The test revealed that the overhead in case-2 was not due to
commit_ts fetching (GetTupleCommitTs).
-- The additional action in case-2 was the error logging of all 10
million update_differ conflicts.
-- To confirm that the additional time was due to logging, I conducted
another test. I removed the "ReportApplyConflict()" call for
update_differ in the code and re-ran test1-case2 (which initially took
~6 minutes). Without conflict logging, the duration was reduced to
"2min 56sec 758 ms".

Test4 - Code Profiling
----------------------------------------------------------------
To narrow down the cause of the time overhead in Test2-case2, did code
profiling patches. Used same setup and test script as Test2.
The overhead in (track_committs=on and detect_conflict=on) case is not
introduced by the commit timestamp fetching(e.g. GetTupleCommitTs).
The main overhead comes from the log reporting which happens when
applying each change:

|--16.57%--ReportApplyConflict
    |--13.17%--errfinish
         --11.53%--EmitErrorReport
             --11.41%--send_message_to_server_log ...
            ...
...
|--0.74%--GetTupleCommitTs"

Thank you Hou-San for helping in Test1 and conducting Test4.

[1]
https://www.postgresql.org/message-id/OS0PR01MB57162919F1D6C55D82D4D89D94B12%40OS0PR01MB5716.jpnprd01.prod.outlook.com

Thanks,

Nisha

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

04 August 2024, 07:34:21

On Friday, July 26, 2024 2:26 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Fri, Jul 26, 2024 at 9:39 AM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > On Thu, Jul 11, 2024 at 7:47 AM Zhijie Hou (Fujitsu)
> > <houzj.fnst@fujitsu.com> wrote:
> > >
> > > On Wednesday, July 10, 2024 5:39 PM shveta malik
> <shveta.malik@gmail.com> wrote:
> > > >
> >
> > > > 2)
> > > > Another case which might confuse user:
> > > >
> > > > CREATE TABLE t1 (pk integer primary key, val1 integer, val2
> > > > integer);
> > > >
> > > > On PUB: insert into t1 values(1,10,10); insert into t1
> > > > values(2,20,20);
> > > >
> > > > On SUB: update t1 set pk=3 where pk=2;
> > > >
> > > > Data on PUB: {1,10,10}, {2,20,20}
> > > > Data on SUB: {1,10,10}, {3,20,20}
> > > >
> > > > Now on PUB: update t1 set val1=200 where val1=20;
> > > >
> > > > On Sub, I get this:
> > > > 2024-07-10 14:44:00.160 IST [648287] LOG:  conflict update_missing
> > > > detected on relation "public.t1"
> > > > 2024-07-10 14:44:00.160 IST [648287] DETAIL:  Did not find the row
> > > > to be updated.
> > > > 2024-07-10 14:44:00.160 IST [648287] CONTEXT:  processing remote
> > > > data for replication origin "pg_16389" during message type
> > > > "UPDATE" for replication target relation "public.t1" in
> > > > transaction 760, finished at 0/156D658
> > > >
> > > > To user, it could be quite confusing, as val1=20 exists on sub but
> > > > still he gets update_missing conflict and the 'DETAIL' is not
> > > > sufficient to give the clarity. I think on HEAD as well (have not
> > > > tested), we will get same behavior i.e. update will be ignored as
> > > > we make search based on RI (pk in this case). So we are not
> > > > worsening the situation, but now since we are detecting conflict, is it
> possible to give better details in 'DETAIL' section indicating what is actually
> missing?
> > >
> > > I think It's doable to report the row value that cannot be found in
> > > the local relation, but the concern is the potential risk of
> > > exposing some sensitive data in the log. This may be OK, as we are
> > > already reporting the key value for constraints violation, so if
> > > others also agree, we can add the row value in the DETAIL as well.
> >
> > This is still awaiting some feedback. I feel it will be good to add
> > some pk value at-least in DETAIL section, like we add for other
> > conflict types.
> >
> 
> I agree that displaying pk where applicable should be okay as we display it at
> other places but the same won't be possible when we do sequence scan to
> fetch the required tuple. So, the message will be different in that case, right?

After some research, I think we can report the key values in DETAIL if the
apply worker uses any unique indexes to find the tuple to update/delete.
Otherwise, we can try to output all column values in DETAIL if the current user
of apply worker has SELECT access to these columns.

This is consistent with what we do when reporting table constraint violation
(e.g. when violating a check constraint, it could output all the column value
if the current has access to all the column):

- First, use super user to create a table.
CREATE TABLE t1 (c1 int, c2 int, c3 int check (c3 < 5));

- 1) using super user to insert a row that violates the constraint. We should
see all the column value.

INSERT INTO t1(c3) VALUES (6);
    ERROR:  new row for relation "t1" violates check constraint "t1_c3_check"
    DETAIL:  Failing row contains (null, null, 6).

- 2) use a user without access to all the columns. We can only see the inserted column and 
CREATE USER regress_priv_user2;
GRANT INSERT (c1, c2, c3) ON t1 TO regress_priv_user2;

SET SESSION AUTHORIZATION regress_priv_user2;
INSERT INTO t1 (c3) VALUES (6);

    ERROR:  new row for relation "t1" violates check constraint "t1_c3_check"
    DETAIL:  Failing row contains (c3) = (6).

To achieve this, I think we can expose the ExecBuildSlotValueDescription
function and use it in conflict reporting. What do you think ?

Best Regards,
Hou zj

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

04 August 2024, 07:52:09

On Friday, August 2, 2024 7:03 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Thu, Aug 1, 2024 at 5:23 PM Amit Kapila <amit.kapila16@gmail.com>
> wrote:
> >
> > On Thu, Aug 1, 2024 at 2:26 PM Hayato Kuroda (Fujitsu)
> > <kuroda.hayato@fujitsu.com> wrote:
> > >
> > > 04. general
> > >
> > > According to the documentation [1], there is another constraint
> > > "exclude", which can cause another type of conflict. But this pattern
> cannot be logged in detail.
> > >
> >
> > As per docs, "exclusion constraints can specify constraints that are
> > more general than simple equality", so I don't think it satisfies the
> > kind of conflicts we are trying to LOG and then in the future patch
> > allows automatic resolution for the same. For example, when we have
> > last_update_wins strategy, we will replace the rows with remote rows
> > when the key column values match which shouldn't be true in general
> > for exclusion constraints. Similarly, we don't want to consider other
> > constraint violations like CHECK to consider as conflicts. We can
> > always extend the basic functionality for more conflicts if required
> > but let's go with reporting straight-forward stuff first.
> >
> 
> It is better to document that exclusion constraints won't be supported. We can
> even write a comment in the code and or commit message that we can extend it
> in the future.

Added.

> 
> *
> + * Return true if the commit timestamp data was found, false otherwise.
> + */
> +bool
> +GetTupleCommitTs(TupleTableSlot *localslot, TransactionId *xmin,
> +RepOriginId *localorigin, TimestampTz *localts)
> 
> This API returns both xmin and commit timestamp, so wouldn't it be better to
> name it as GetTupleTransactionInfo or something like that?

The suggested name looks better. Addressed in the patch.

> 
> I have made several changes in the attached top-up patch. These include
> changes in the comments, docs, function names, etc.

Thanks! I have reviewed and merged them in the patch.

Here is the V11 patch set which addressed above and Kuroda-san[1] comments.

Note that we may remove the 0002 patch in the next version as we didn't see
performance effect from the detection logic.

[1]
https://www.postgresql.org/message-id/TYAPR01MB569224262F44875973FAF344F5B22%40TYAPR01MB5692.jpnprd01.prod.outlook.com

Best Regards,
Hou zj

Dear Hou,

> 
> Here is the V11 patch set which addressed above and Kuroda-san[1] comments.
>

Thanks for updating the patch. I read 0001 again and I don't have critical comments for now.
I found some cosmetic issues (e.g., lines should be shorter than 80 columns) and
attached the fix patch. Feel free to include in the next version.
    
Best regards,
Hayato Kuroda
FUJITSU LIMITED

Attachment

fixes_for_v11.patch

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

07 August 2024, 05:23:36

On Tue, Aug 6, 2024 at 1:45 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> On Monday, August 5, 2024 6:52 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Sun, Aug 4, 2024 at 1:22 PM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
> > wrote:
> > >
> > > On Friday, August 2, 2024 7:03 PM Amit Kapila <amit.kapila16@gmail.com>
> > wrote:
> > > >
> > >
> > > Here is the V11 patch set which addressed above and Kuroda-san[1]
> > comments.
> > >
> >
> > A few design-level points:
> >
> > *
> > @@ -525,10 +602,33 @@ ExecSimpleRelationInsert(ResultRelInfo
> > *resultRelInfo,
> >   /* OK, store the tuple and create index entries for it */
> >   simple_table_tuple_insert(resultRelInfo->ri_RelationDesc, slot);
> >
> > + conflictindexes = resultRelInfo->ri_onConflictArbiterIndexes;
> > +
> >   if (resultRelInfo->ri_NumIndices > 0)
> >   recheckIndexes = ExecInsertIndexTuples(resultRelInfo,
> > -    slot, estate, false, false,
> > -    NULL, NIL, false);
> > +    slot, estate, false,
> > +    conflictindexes ? true : false,
> > +    &conflict,
> > +    conflictindexes, false);
> > +
> > + /*
> > + * Checks the conflict indexes to fetch the conflicting local tuple
> > + * and reports the conflict. We perform this check here, instead of
> > + * performing an additional index scan before the actual insertion and
> > + * reporting the conflict if any conflicting tuples are found. This is
> > + * to avoid the overhead of executing the extra scan for each INSERT
> > + * operation, even when no conflict arises, which could introduce
> > + * significant overhead to replication, particularly in cases where
> > + * conflicts are rare.
> > + *
> > + * XXX OTOH, this could lead to clean-up effort for dead tuples added
> > + * in heap and index in case of conflicts. But as conflicts shouldn't
> > + * be a frequent thing so we preferred to save the performance overhead
> > + * of extra scan before each insertion.
> > + */
> > + if (conflict)
> > + CheckAndReportConflict(resultRelInfo, estate, CT_INSERT_EXISTS,
> > +    recheckIndexes, slot);
> >
> > I was thinking about this case where we have some pros and cons of doing
> > additional scans only after we found the conflict. I was wondering how we will
> > handle the resolution strategy for this when we have to remote_apply the tuple
> > for insert_exists/update_exists cases.
> > We would have already inserted the remote tuple in the heap and index before
> > we found the conflict which means we have to roll back that change and then
> > start a forest transaction to perform remote_apply which probably has to
> > update the existing tuple. We may have to perform something like speculative
> > insertion and then abort it. That doesn't sound cheap either. Do you have any
> > better ideas?
>
> Since most of the codes of conflict detection can be reused in the later
> resolution patch. I am thinking we can go for re-scan after insertion approach
> for detection patch. Then in resolution patch we can probably have a check in
> the patch that if the resolver is remote_apply/last_update_win we detect
> conflict before, otherwise detect it after. This way we can save an
> subscription option in the detection patch because we are not introducing overhead
> for the detection.
>

Sounds reasonable to me.

>
>
> >
> > *
> > -ERROR:  duplicate key value violates unique constraint "test_pkey"
> > -DETAIL:  Key (c)=(1) already exists.
> > +ERROR:  conflict insert_exists detected on relation "public.test"
> > +DETAIL:  Key (c)=(1) already exists in unique index "t_pkey", which
> > was modified locally in transaction 740 at 2024-06-26 10:47:04.727375+08.
> >
> > I think the format to display conflicts is not very clear. The conflict should be
> > apparent just by seeing the LOG/ERROR message. I am thinking of something
> > like below:
> >
> > LOG: CONFLICT: <insert_exisits or whatever names we document>;
> > DESCRIPTION: If any .. ; RESOLUTION: (This one can be added later)
> > DEATAIL: remote_tuple (tuple values); local_tuple (tuple values);
> >
> > With the above, one can easily identify the conflict's reason and action taken by
> > apply worker.
>
> Thanks for the idea! I thought about few styles based on the suggested format,
> what do you think about the following ?
>
> ---
> Version 1
> ---
> LOG: CONFLICT: insert_exists; DESCRIPTION: remote INSERT violates unique constraint "uniqueindex" on relation
"public.test".
> DETAIL: Existing local tuple (a, b, c) = (2, 3, 4) xid=123,origin="pub",timestamp=xxx; remote tuple (a, b, c) = (2,
4,5). 
>

Won't this case be ERROR? If so, the error message format like the
above appears odd to me because in some cases, the user may want to
add some filter based on the error message though that is not ideal.
Also, the primary error message starts with a small case letter and
should be short.

> LOG: CONFLICT: update_differ; DESCRIPTION: updating a row with key (a, b) = (2, 4) on relation "public.test" was
modifiedby a different source. 
> DETAIL: Existing local tuple (a, b, c) = (2, 3, 4) xid=123,origin="pub",timestamp=xxx; remote tuple (a, b, c) = (2,
4,5). 
>
> LOG: CONFLICT: update_missing; DESCRIPTION: did not find the row with key (a, b) = (2, 4) on "public.test" to update.
> DETAIL: remote tuple (a, b, c) = (2, 4, 5).
>
> ---
> Version 2
> It moves most the details to the DETAIL line compared to version 1.
> ---
> LOG: CONFLICT: insert_exists on relation "public.test".
> DETAIL: Key (a)=(1) already exists in unique index "uniqueindex", which was modified by origin "pub" in transaction
123at 2024xxx; 
>                 Existing local tuple (a, b, c) = (1, 3, 4), remote tuple (a, b, c) = (1, 4, 5).
>
> LOG: CONFLICT: update_differ on relation "public.test".
> DETAIL: Updating a row with key (a, b) = (2, 4) that was modified by a different origin "pub" in transaction 123 at
2024xxx;
>                 Existing local tuple (a, b, c) = (2, 3, 4); remote tuple (a, b, c) = (2, 4, 5).
>
> LOG: CONFLICT: update_missing on relation "public.test".
> DETAIL: Did not find the row with key (a, b) = (2, 4) to update;
>                 Remote tuple (a, b, c) = (2, 4, 5).
>

I think we can combine sentences with full stop.

...
> ---
> Version 3
> It is similar to the style in the current patch, I only added the key value for
> differ and missing conflicts without outputting the complete
> remote/local tuple value.
> ---
> LOG: conflict insert_exists detected on relation "public.test".
> DETAIL: Key (a)=(1) already exists in unique index "uniqueindex", which was modified by origin "pub" in transaction
123at 2024xxx. 
>

For ERROR messages this appears suitable.

Considering all the above points, I propose yet another version:

LOG: conflict detected for relation "public.test": conflict=insert_exists
DETAIL: Key (a)=(1) already exists in unique index "uniqueindex",
which was modified by the origin "pub" in transaction 123 at 2024xxx.
Existing local tuple (a, b, c) = (1, 3, 4), remote tuple (a, b, c) =
(1, 4, 5).

LOG: conflict detected for relation "public.test": conflict=update_differ
DETAIL: Updating a row with key (a, b) = (2, 4) that was modified by a
different origin "pub" in transaction 123 at 2024xxx. Existing local
tuple (a, b, c) = (2, 3, 4); remote tuple (a, b, c) = (2, 4, 5).

LOG:  conflict detected for relation "public.test": conflict=update_missing
DETAIL: Could not find the row with key (a, b) = (2, 4) to update.
Remote tuple (a, b, c) = (2, 4, 5).


--
With Regards,
Amit Kapila.

RE: Conflict detection and logging in logical replication

From

"Hayato Kuroda (Fujitsu)"

Date:

07 August 2024, 06:59:59

Dear Hou,

While playing with the 0003 patch (the patch may not be ready), I found that
when the insert_exists event occurred, both apply_error_count and insert_exists_count
was counted.

```
-- insert a tuple on the subscriber
subscriber =# INSERT INTO tab VALUES (1);

-- insert the same tuple on the publisher, which causes insert_exists conflict
publisher =# INSERT INTO tab VALUES (1);

-- after some time...
subscriber =# SELECT * FROM pg_stat_subscription_stats;
-[ RECORD 1 ]--------+------
subid                | 16389
subname              | sub
apply_error_count    | 16
sync_error_count     | 0
insert_exists_count  | 16
update_differ_count  | 0
update_exists_count  | 0
update_missing_count | 0
delete_differ_count  | 0
delete_missing_count | 0
stats_reset          |
```

Not tested, but I think this could also happen for the update_exists_count case,
or sync_error_count may be counted when the tablesync worker detects the conflict.

IIUC, the reason is that pgstat_report_subscription_error() is called in the
PG_CATCH part in start_apply() even after ReportApplyConflict(ERROR) is called.

What do you think of the current behavior? I wouldn't say I like that the same
phenomenon is counted as several events. E.g., in the case of vacuum, the entry
seemed to be separated based on the process by backends or autovacuum.
I feel the spec is unfamiliar in that only insert_exists and update_exists are
counted duplicated with the apply_error_count.

An easy fix is to introduce a global variable which is turned on when the conflict
is found.

Thought?

Best regards,
Hayato Kuroda
FUJITSU LIMITED

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

07 August 2024, 07:38:08

On Wednesday, August 7, 2024 3:00 PM Kuroda, Hayato/黒田 隼人 <kuroda.hayato@fujitsu.com> wrote:
> 
> While playing with the 0003 patch (the patch may not be ready), I found that
> when the insert_exists event occurred, both apply_error_count and
> insert_exists_count was counted.

Thanks for testing. 0003 is a separate feature which we might review
after the 0001 is in a good shape or committed.

> 
> ```
> -- insert a tuple on the subscriber
> subscriber =# INSERT INTO tab VALUES (1);
> 
> -- insert the same tuple on the publisher, which causes insert_exists conflict
> publisher =# INSERT INTO tab VALUES (1);
> 
> -- after some time...
> subscriber =# SELECT * FROM pg_stat_subscription_stats; -[ RECORD
> 1 ]--------+------
> subid                | 16389
> subname              | sub
> apply_error_count    | 16
> sync_error_count     | 0
> insert_exists_count  | 16
> update_differ_count  | 0
> update_exists_count  | 0
> update_missing_count | 0
> delete_differ_count  | 0
> delete_missing_count | 0
> stats_reset          |
> ```
> 
> Not tested, but I think this could also happen for the update_exists_count case,
> or sync_error_count may be counted when the tablesync worker detects the
> conflict.
> 
> IIUC, the reason is that pgstat_report_subscription_error() is called in the
> PG_CATCH part in start_apply() even after ReportApplyConflict(ERROR) is
> called.
> 
> What do you think of the current behavior? I wouldn't say I like that the same
> phenomenon is counted as several events. E.g., in the case of vacuum, the
> entry seemed to be separated based on the process by backends or
> autovacuum.

I think this is as expected. When the insert conflicts, it will report an ERROR
so both the conflict count and error out are incremented which looks reasonable
to me. The default behavior for each conflict could be different and is
documented, I think It's clear that insert_exists will cause an ERROR while
delete_missing or .. will not.

In addition, we might support a resolution called "error" which is to report an
ERROR When facing the specified conflict, it would be a bit confusing to me if
the apply_error_count Is not incremented on the specified conflict, when I set
resolution to ERROR.

> I feel the spec is unfamiliar in that only insert_exists and update_exists are
> counted duplicated with the apply_error_count.
> 
> An easy fix is to introduce a global variable which is turned on when the conflict
> is found.

I am not sure about the benefit of changing the current behavior in the patch.
And it will change the existing behavior, because before the conflict detection
patch, the apply_error_count is incremented on each unique key violation, while
after the detection patch, it stops incrementing the apply_error and only
conflict_count is incremented.

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

07 August 2024, 08:41:43

On Wed, Aug 7, 2024 at 1:08 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> On Wednesday, August 7, 2024 3:00 PM Kuroda, Hayato/黒田 隼人 <kuroda.hayato@fujitsu.com> wrote:
> >
> > While playing with the 0003 patch (the patch may not be ready), I found that
> > when the insert_exists event occurred, both apply_error_count and
> > insert_exists_count was counted.
>
> Thanks for testing. 0003 is a separate feature which we might review
> after the 0001 is in a good shape or committed.
>
> >
> > ```
> > -- insert a tuple on the subscriber
> > subscriber =# INSERT INTO tab VALUES (1);
> >
> > -- insert the same tuple on the publisher, which causes insert_exists conflict
> > publisher =# INSERT INTO tab VALUES (1);
> >
> > -- after some time...
> > subscriber =# SELECT * FROM pg_stat_subscription_stats; -[ RECORD
> > 1 ]--------+------
> > subid                | 16389
> > subname              | sub
> > apply_error_count    | 16
> > sync_error_count     | 0
> > insert_exists_count  | 16
> > update_differ_count  | 0
> > update_exists_count  | 0
> > update_missing_count | 0
> > delete_differ_count  | 0
> > delete_missing_count | 0
> > stats_reset          |
> > ```
> >
> > Not tested, but I think this could also happen for the update_exists_count case,
> > or sync_error_count may be counted when the tablesync worker detects the
> > conflict.
> >
> > IIUC, the reason is that pgstat_report_subscription_error() is called in the
> > PG_CATCH part in start_apply() even after ReportApplyConflict(ERROR) is
> > called.
> >
> > What do you think of the current behavior? I wouldn't say I like that the same
> > phenomenon is counted as several events. E.g., in the case of vacuum, the
> > entry seemed to be separated based on the process by backends or
> > autovacuum.
>
> I think this is as expected. When the insert conflicts, it will report an ERROR
> so both the conflict count and error out are incremented which looks reasonable
> to me. The default behavior for each conflict could be different and is
> documented, I think It's clear that insert_exists will cause an ERROR while
> delete_missing or .. will not.
>

I had also observed this behaviour during my testing of stats patch.
But I found this behaviour to be okay. IMO, apply_error_count should
account any error caused during applying and thus should incorporate
insert-exists error-count too.

> In addition, we might support a resolution called "error" which is to report an
> ERROR When facing the specified conflict, it would be a bit confusing to me if
> the apply_error_count Is not incremented on the specified conflict, when I set
> resolution to ERROR.
>
> > I feel the spec is unfamiliar in that only insert_exists and update_exists are
> > counted duplicated with the apply_error_count.
> >
> > An easy fix is to introduce a global variable which is turned on when the conflict
> > is found.
>
> I am not sure about the benefit of changing the current behavior in the patch.
> And it will change the existing behavior, because before the conflict detection
> patch, the apply_error_count is incremented on each unique key violation, while
> after the detection patch, it stops incrementing the apply_error and only
> conflict_count is incremented.
>

thanks
Shveta

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

09 August 2024, 06:59:29

On Wednesday, August 7, 2024 1:24 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Tue, Aug 6, 2024 at 1:45 PM Zhijie Hou (Fujitsu)
> > Thanks for the idea! I thought about few styles based on the suggested
> format,
> > what do you think about the following ?
> >
> > ---
> > Version 1
> > ---
> > LOG: CONFLICT: insert_exists; DESCRIPTION: remote INSERT violates
> unique constraint "uniqueindex" on relation "public.test".
> > DETAIL: Existing local tuple (a, b, c) = (2, 3, 4)
> xid=123,origin="pub",timestamp=xxx; remote tuple (a, b, c) = (2, 4, 5).
> >
> 
> Won't this case be ERROR? If so, the error message format like the
> above appears odd to me because in some cases, the user may want to
> add some filter based on the error message though that is not ideal.
> Also, the primary error message starts with a small case letter and
> should be short.
> 
> > LOG: CONFLICT: update_differ; DESCRIPTION: updating a row with key (a,
> b) = (2, 4) on relation "public.test" was modified by a different source.
> > DETAIL: Existing local tuple (a, b, c) = (2, 3, 4)
> xid=123,origin="pub",timestamp=xxx; remote tuple (a, b, c) = (2, 4, 5).
> >
> > LOG: CONFLICT: update_missing; DESCRIPTION: did not find the row with
> key (a, b) = (2, 4) on "public.test" to update.
> > DETAIL: remote tuple (a, b, c) = (2, 4, 5).
> >
> > ---
> > Version 2
> > It moves most the details to the DETAIL line compared to version 1.
> > ---
> > LOG: CONFLICT: insert_exists on relation "public.test".
> > DETAIL: Key (a)=(1) already exists in unique index "uniqueindex", which
> was modified by origin "pub" in transaction 123 at 2024xxx;
> >                 Existing local tuple (a, b, c) = (1, 3, 4), remote tuple (a, b, c)
> = (1, 4, 5).
> >
> > LOG: CONFLICT: update_differ on relation "public.test".
> > DETAIL: Updating a row with key (a, b) = (2, 4) that was modified by a
> different origin "pub" in transaction 123 at 2024xxx;
> >                 Existing local tuple (a, b, c) = (2, 3, 4); remote tuple (a, b, c)
> = (2, 4, 5).
> >
> > LOG: CONFLICT: update_missing on relation "public.test".
> > DETAIL: Did not find the row with key (a, b) = (2, 4) to update;
> >                 Remote tuple (a, b, c) = (2, 4, 5).
> >
> 
> I think we can combine sentences with full stop.
> 
> ...
> > ---
> > Version 3
> > It is similar to the style in the current patch, I only added the key value for
> > differ and missing conflicts without outputting the complete
> > remote/local tuple value.
> > ---
> > LOG: conflict insert_exists detected on relation "public.test".
> > DETAIL: Key (a)=(1) already exists in unique index "uniqueindex", which
> was modified by origin "pub" in transaction 123 at 2024xxx.
> >
> 
> For ERROR messages this appears suitable.
> 
> Considering all the above points, I propose yet another version:
> 
> LOG: conflict detected for relation "public.test": conflict=insert_exists
> DETAIL: Key (a)=(1) already exists in unique index "uniqueindex",
> which was modified by the origin "pub" in transaction 123 at 2024xxx.
> Existing local tuple (a, b, c) = (1, 3, 4), remote tuple (a, b, c) =
> (1, 4, 5).
> 
> LOG: conflict detected for relation "public.test": conflict=update_differ
> DETAIL: Updating a row with key (a, b) = (2, 4) that was modified by a
> different origin "pub" in transaction 123 at 2024xxx. Existing local
> tuple (a, b, c) = (2, 3, 4); remote tuple (a, b, c) = (2, 4, 5).
> 
> LOG:  conflict detected for relation "public.test": conflict=update_missing
> DETAIL: Could not find the row with key (a, b) = (2, 4) to update.
> Remote tuple (a, b, c) = (2, 4, 5).

Here is the V12 patch that improved the log format as discussed. I also fixed a
bug in previous version where it reported the wrong column value in the DETAIL
message.

In the latest patch, the DETAIL line comprises two parts: 1. Explanation of the
conflict type, including the tuple value used to search the existing local
tuple provided for update or deletion, or the tuple value causing the unique
constraint violation. 2. Display of the complete existing local tuple and the
remote tuple, if any.

I also addressed Shveta's comments and tried to merge Kuroda-san's changes[2] to
the new codes.

And the 0002(new sub option) patch is removed as discussed. The 0003(stats
collection) patch is also removed temporarily, we can bring it back After
finishing the 0001 work.

[1] https://www.postgresql.org/message-id/CAJpy0uAjJci%2BOtm4ANU0__-2qqhH2cALp8hQw5pBjNZyREF7rg%40mail.gmail.com
[2]
https://www.postgresql.org/message-id/TYAPR01MB5692224DB472AA3FA58E1D1AF5B82%40TYAPR01MB5692.jpnprd01.prod.outlook.com

Best Regards,
Hou zj

Attachment

v12-0001-Detect-and-log-conflicts-in-logical-replication.patch

Re: Conflict detection and logging in logical replication

From

Michail Nikolaev

Date:

09 August 2024, 11:45:12

Hello, everyone.

There are some comments on this patch related to issue [0].
In short: any DirtySnapshot index scan may fail to find an existing tuple in the case of a concurrent update.

- FindConflictTuple may return false negative result in the case of concurrent update because ExecCheckIndexConstraints uses SnapshotDirty.
- As a result, CheckAndReportConflict may fail to report the conflict.
- In apply_handle_update_internal we may get an CT_UPDATE_MISSING instead of CT_UPDATE_DIFFER
- In apply_handle_update_internal we may get an CT_DELETE_MISSING instead of CT_DELETE_DIFFER
- In apply_handle_tuple_routing we may get an CT_UPDATE_MISSING instead of CT_UPDATE_DIFFER

If you're interested, I could create a test to reproduce the issue within the context of logical replication. Issue [0] itself includes a test case to replicate the problem.

It also seems possible that a conflict could be resolved by a concurrent update before the call to CheckAndReportConflict, which means there's no guarantee that the conflict will be reported correctly.
Should we be concerned about this?

[0]: https://commitfest.postgresql.org/49/5151/

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

12 August 2024, 03:33:05

On Friday, August 9, 2024 7:45 PM Michail Nikolaev <michail.nikolaev@gmail.com>  wrote:
> There are some comments on this patch related to issue [0]. In short: any
> DirtySnapshot index scan may fail to find an existing tuple in the case of a
> concurrent update.
> 
> - FindConflictTuple may return false negative result in the case of concurrent update because >
ExecCheckIndexConstraintsuses SnapshotDirty.
 
> - As a result, CheckAndReportConflict may fail to report the conflict.
> - In apply_handle_update_internal we may get an CT_UPDATE_MISSING instead of CT_UPDATE_DIFFER
> - In apply_handle_update_internal we may get an CT_DELETE_MISSING instead of CT_DELETE_DIFFER
> - In apply_handle_tuple_routing we may get an CT_UPDATE_MISSING instead of CT_UPDATE_DIFFER
> 
> If you're interested, I could create a test to reproduce the issue within the
> context of logical replication. Issue [0] itself includes a test case to
> replicate the problem.
> 
> It also seems possible that a conflict could be resolved by a concurrent update
> before the call to CheckAndReportConflict, which means there's no guarantee
> that the conflict will be reported correctly. Should we be concerned about
> this?

Thanks for reporting.

I think this is an independent issue which can be discussed separately in the
original thread[1], and I have replied to that thread.

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

12 August 2024, 04:00:34

On Fri, Aug 9, 2024 at 12:29 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Here is the V12 patch that improved the log format as discussed.
>

*
diff --git a/src/test/subscription/out b/src/test/subscription/out
new file mode 100644
index 0000000000..2b68e9264a
--- /dev/null
+++ b/src/test/subscription/out
@@ -0,0 +1,29 @@
+make -C ../../../src/backend generated-headers
+make[1]: Entering directory '/home/houzj/postgresql/src/backend'
+make -C ../include/catalog generated-headers
+make[2]: Entering directory '/home/houzj/postgresql/src/include/catalog'
+make[2]: Nothing to be done for 'generated-headers'.
+make[2]: Leaving directory '/home/houzj/postgresql/src/include/catalog'
+make -C nodes generated-header-symlinks
+make[2]: Entering directory '/home/houzj/postgresql/src/backend/nodes'
+make[2]: Nothing to be done for 'generated-header-symlinks'.
+make[2]: Leaving directory '/home/houzj/postgresql/src/backend/nodes'
+make -C utils generated-header-symlinks
+make[2]: Entering directory '/home/houzj/postgresql/src/backend/utils'
+make -C adt jsonpath_gram.h
+make[3]: Entering directory '/home/houzj/postgresql/src/backend/utils/adt'
+make[3]: 'jsonpath_gram.h' is up to date.
+make[3]: Leaving directory '/home/houzj/postgresql/src/backend/utils/adt'
+make[2]: Leaving directory '/home/houzj/postgresql/src/backend/utils'
+make[1]: Leaving directory '/home/houzj/postgresql/src/backend'
+rm -rf '/home/houzj/postgresql'/tmp_install
+/usr/bin/mkdir -p '/home/houzj/postgresql'/tmp_install/log
+make -C '../../..' DESTDIR='/home/houzj/postgresql'/tmp_install
install >'/home/houzj/postgresql'/tmp_install/log/install.log 2>&1
+make -j1  checkprep >>'/home/houzj/postgresql'/tmp_install/log/install.log 2>&1
+PATH="/home/houzj/postgresql/tmp_install/home/houzj/pgsql/bin:/home/houzj/postgresql/src/test/subscription:$PATH"
LD_LIBRARY_PATH="/home/houzj/postgresql/tmp_install/home/houzj/pgsql/lib"
INITDB_TEMPLATE='/home/houzj/postgresql'/tmp_install/initdb-template
initdb --auth trust --no-sync --no-instructions --lc-messages=C
--no-clean '/home/houzj/postgresql'/tmp_install/initdb-template
>>'/home/houzj/postgresql'/tmp_install/log/initdb-template.log 2>&1
+echo "# +++ tap check in src/test/subscription +++" && rm -rf
'/home/houzj/postgresql/src/test/subscription'/tmp_check &&
/usr/bin/mkdir -p
'/home/houzj/postgresql/src/test/subscription'/tmp_check && cd . &&
TESTLOGDIR='/home/houzj/postgresql/src/test/subscription/tmp_check/log'
TESTDATADIR='/home/houzj/postgresql/src/test/subscription/tmp_check'
PATH="/home/houzj/postgresql/tmp_install/home/houzj/pgsql/bin:/home/houzj/postgresql/src/test/subscription:$PATH"
LD_LIBRARY_PATH="/home/houzj/postgresql/tmp_install/home/houzj/pgsql/lib"
INITDB_TEMPLATE='/home/houzj/postgresql'/tmp_install/initdb-template
PGPORT='65432' top_builddir='/home/houzj/postgresql/src/test/subscription/../../..'
PG_REGRESS='/home/houzj/postgresql/src/test/subscription/../../../src/test/regress/pg_regress'
/usr/bin/prove -I ../../../src/test/perl/ -I .  t/013_partition.pl
+# +++ tap check in src/test/subscription +++
+t/013_partition.pl .. ok
+All tests successful.
+Files=1, Tests=73,  4 wallclock secs ( 0.02 usr  0.00 sys +  0.59
cusr  0.21 csys =  0.82 CPU)
+Result: PASS

The above is added to the patch by mistake. Can you please remove it
from the patch unless there is a reason?

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

12 August 2024, 11:40:47

On Fri, Aug 9, 2024 at 12:29 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Here is the V12 patch that improved the log format as discussed.
>

Review comments:
===============
1. The patch doesn't display the remote tuple for delete_differ case.
However, it shows the remote tuple correctly for update_differ. Is
there a reason for the same? See below messages:

update_differ:
--------------
LOG:  conflict detected on relation "public.t1": conflict=update_differ
DETAIL:  Updating the row containing (c1)=(1) that was modified
locally in transaction 806 at 2024-08-12 11:48:14.970002+05:30.
        Existing local tuple (1, 3, arun      ); remote tuple (1, 3,
ajay      ).
...

delete_differ
--------------
LOG:  conflict detected on relation "public.t1": conflict=delete_differ
DETAIL:  Deleting the row containing (c1)=(1) that was modified by
locally in transaction 809 at 2024-08-12 14:15:41.966467+05:30.
        Existing local tuple (1, 3, arun      ).

Note this happens when the publisher table has a REPLICA IDENTITY FULL
and the subscriber table has primary_key. It would be better to keep
the messages consistent. One possibility is that we remove
key/old_tuple from the first line of the DETAIL message and display it
in the second line as Existing local tuple <local_tuple>; remote tuple
<..>; key <...>

2. Similar to above, the remote tuple is not displayed in
delete_missing but displayed in updated_missing type of conflict. If
we follow the style mentioned in the previous point then the DETAIL
message: "DETAIL:  Did not find the row containing (c1)=(1) to be
updated." can also be changed to: "DETAIL:  Could not find the row to
be updated." followed by other detail.

3. The detail of insert_exists is confusing.

ERROR:  conflict detected on relation "public.t1": conflict=insert_exists
DETAIL:  Key (c1)=(1) already exists in unique index "t1_pkey", which
was modified locally in transaction 802 at 2024-08-12
11:11:31.252148+05:30.

It sounds like the key value "(c1)=(1)" in the index is modified. How
about changing slightly as: "Key (c1)=(1) already exists in unique
index "t1_pkey", modified locally in transaction 802 at 2024-08-12
11:11:31.252148+05:30."? Feel free to propose if anything better comes
to your mind.

4.
if (localorigin == InvalidRepOriginId)
+ appendStringInfo(&err_detail, _("Deleting the row containing %s that
was modified by locally in transaction %u at %s."),
+ val_desc, localxmin, timestamptz_to_str(localts));

Typo in the above message. /modified by locally/modified locally

5.
@@ -2661,6 +2662,29 @@ apply_handle_update_internal(ApplyExecutionData *edata,
{
...
found = FindReplTupleInLocalRel(edata, localrel,
&relmapentry->remoterel,
localindexoid,
remoteslot, &localslot);
...
...
+
+ ReportApplyConflict(LOG, CT_UPDATE_DIFFER, relinfo,
+ GetRelationIdentityOrPK(localrel),

To find the tuple, we may have used an index other than Replica
Identity or PK (see IsIndexUsableForReplicaIdentityFull), but while
reporting conflict we don't consider such an index. I think the reason
is that such an index scan wouldn't have resulted in a unique tuple
and that is why we always compare the complete tuple in such cases. Is
that the reason? Can we write a comment to make it clear?

6.
void ReportApplyConflict(int elevel, ConflictType type,
+ ResultRelInfo *relinfo, Oid indexoid,
+ TransactionId localxmin,
+ RepOriginId localorigin,
+ TimestampTz localts,
+ TupleTableSlot *searchslot,
+ TupleTableSlot *localslot,
+ TupleTableSlot *remoteslot,
+ EState *estate);

The prototype looks odd with pointers and non-pointer variables in
mixed order. How about arranging parameters in the following order:
Estate, ResultRelInfo, TupleTableSlot *searchslot, TupleTableSlot
*localslot, TupleTableSlot *remoteslot, Oid indexoid, TransactionId
localxmin, RepOriginId localorigin, TimestampTz localts?

7. Like above, check the parameters of other functions like
errdetail_apply_conflict, build_index_value_desc,
build_tuple_value_details, etc.

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

Nisha Moond

Date:

13 August 2024, 03:57:23

On Mon, Aug 5, 2024 at 10:05 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Mon, Aug 5, 2024 at 9:19 AM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Fri, Aug 2, 2024 at 6:28 PM Nisha Moond <nisha.moond412@gmail.com> wrote:
> > >
> > > Performance tests done on the v8-0001 and v8-0002 patches, available at [1].
> > >
> >
> > Thanks for doing the detailed tests for this patch.
> >
> > > The purpose of the performance tests is to measure the impact on
> > > logical replication with track_commit_timestamp enabled, as this
> > > involves fetching the commit_ts data to determine
> > > delete_differ/update_differ conflicts.
> > >
> > > Fortunately, we did not see any noticeable overhead from the new
> > > commit_ts fetch and comparison logic. The only notable impact is
> > > potential overhead from logging conflicts if they occur frequently.
> > > Therefore, enabling conflict detection by default seems feasible, and
> > > introducing a new detect_conflict option may not be necessary.
> > >
> > ...
> > >
> > > Test 1: create conflicts on Sub using pgbench.
> > > ----------------------------------------------------------------
> > > Setup:
> > >  - Both publisher and subscriber have pgbench tables created as-
> > >       pgbench -p $node1_port postgres -qis 1
> > >  - At Sub, a subscription created for all the changes from Pub node.
> > >
> > > Test Run:
> > >  - To test, ran pgbench for 15 minutes on both nodes simultaneously,
> > > which led to concurrent updates and update_differ conflicts on the
> > > Subscriber node.
> > >  Command used to run pgbench on both nodes-
> > >         ./pgbench postgres -p 8833 -c 10 -j 3 -T 300 -P 20
> > >
> > > Results:
> > > For each case, note the “tps” and total time taken by the apply-worker
> > > on Sub to apply the changes coming from Pub.
> > >
> > > Case1: track_commit_timestamp = off, detect_conflict = off
> > >     Pub-tps = 9139.556405
> > >     Sub-tps = 8456.787967
> > >     Time of replicating all the changes: 19min 28s
> > > Case 2 : track_commit_timestamp = on, detect_conflict = on
> > >     Pub-tps = 8833.016548
> > >     Sub-tps = 8389.763739
> > >     Time of replicating all the changes: 20min 20s
> > >
> >
> > Why is there a noticeable tps (~3%) reduction in publisher TPS? Is it
> > the impact of track_commit_timestamp = on or something else?

When both the publisher and subscriber nodes are on the same machine,
we observe a decrease in the publisher's TPS in case when
'track_commit_timestamp' is ON for the subscriber. Testing on pgHead
(without the patch) also showed a similar reduction in the publisher's
TPS.

Test Setup: The test was conducted with the same setup as Test-1.

Results:
Case 1: pgHead - 'track_commit_timestamp' = OFF
  - Pub TPS: 9306.25
  - Sub TPS: 8848.91
Case 2: pgHead - 'track_commit_timestamp' = ON
  - Pub TPS: 8915.75
  - Sub TPS: 8667.12

On pgHead too, there was a ~400tps reduction in the publisher when
'track_commit_timestamp' was enabled on the subscriber.

Additionally, code profiling of the walsender on the publisher showed
that the overhead in Case-2 was mainly in the DecodeCommit() call
stack, causing slower write operations, especially in
logicalrep_write_update() and OutputPluginWrite().

case1 : 'track_commit_timestamp' = OFF
--11.57%--xact_decode
| |  DecodeCommit
| |  ReorderBufferCommit
...
| |  --6.10%--pgoutput_change
| |    |
| |    |--3.09%--logicalrep_write_update
| |      ....
| |      |--2.01%--OutputPluginWrite
| |            |--1.97%--WalSndWriteData

case2: 'track_commit_timestamp' = ON
|--53.19%--xact_decode
| |  DecodeCommit
| |  ReorderBufferCommit
...
| |     --30.25%--pgoutput_change
| |      |
| |      |--15.23%--logicalrep_write_update
| |      ....
| |      |--9.82%--OutputPluginWrite
| |           |--9.57%--WalSndWriteData

-- In Case 2, the subscriber's process of writing timestamp data for
millions of rows appears to have impacted all write operations on the
machine.

To confirm the profiling results, we conducted the same test with the
publisher and subscriber on separate machines.

Results:
Case 1: 'track_commit_timestamp' = OFF
  - Run 1: Pub TPS: 2144.10, Sub TPS: 2216.02
  - Run 2: Pub TPS: 2159.41, Sub TPS: 2233.82

Case 2: 'track_commit_timestamp' = ON
  - Run 1: Pub TPS: 2174.39, Sub TPS: 2226.89
  - Run 2: Pub TPS: 2148.92, Sub TPS: 2224.80

Note: The machines used in this test were not as powerful as the one
used in the earlier tests, resulting in lower overall TPS (~2k vs.
~8-9k).
However, the results show no significant reduction in the publisher's
TPS, indicating minimal impact when the nodes are run on separate
machines.

> Was track_commit_timestamp enabled only on subscriber (as needed) or
> on both publisher and subscriber? Nisha, can you please confirm from
> your logs?

Yes, track_commit_timestamp was enabled only on the subscriber.

> > > Case3: track_commit_timestamp = on, detect_conflict = off
> > >     Pub-tps = 8886.101726
> > >     Sub-tps = 8374.508017
> > >     Time of replicating all the changes: 19min 35s
> > > Case 4: track_commit_timestamp = off, detect_conflict = on
> > >     Pub-tps = 8981.924596
> > >     Sub-tps = 8411.120808
> > >     Time of replicating all the changes: 19min 27s
> > >
> > > **The difference of TPS between each case is small. While I can see a
> > > slight increase of the replication time (about 5%), when enabling both
> > > track_commit_timestamp and detect_conflict.
> > >
> >
> > The difference in TPS between case 1 and case 2 is quite visible.
> > IIUC, the replication time difference is due to the logging of
> > conflicts, right?
> >

Right, the major difference is due to the logging of conflicts.

--
Thanks,
Nisha

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

13 August 2024, 04:39:15

On Monday, August 12, 2024 7:41 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Fri, Aug 9, 2024 at 12:29 PM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > Here is the V12 patch that improved the log format as discussed.
> >
> 
> Review comments:

Thanks for the comments.

> ===============
> 1. The patch doesn't display the remote tuple for delete_differ case.
> However, it shows the remote tuple correctly for update_differ. Is
> there a reason for the same? See below messages:
> 
> update_differ:
> --------------
> LOG:  conflict detected on relation "public.t1": conflict=update_differ
> DETAIL:  Updating the row containing (c1)=(1) that was modified
> locally in transaction 806 at 2024-08-12 11:48:14.970002+05:30.
>         Existing local tuple (1, 3, arun      ); remote tuple (1, 3,
> ajay      ).
> ...
> 
> delete_differ
> --------------
> LOG:  conflict detected on relation "public.t1": conflict=delete_differ
> DETAIL:  Deleting the row containing (c1)=(1) that was modified by
> locally in transaction 809 at 2024-08-12 14:15:41.966467+05:30.
>         Existing local tuple (1, 3, arun      ).
> 
> Note this happens when the publisher table has a REPLICA IDENTITY FULL
> and the subscriber table has primary_key. It would be better to keep
> the messages consistent. One possibility is that we remove
> key/old_tuple from the first line of the DETAIL message and display it
> in the second line as Existing local tuple <local_tuple>; remote tuple
> <..>; key <...>

Agreed. I thought that in delete_differ/missing cases, the remote tuple is covered
In the key values in the first sentence. To be consistent, I have moved the column-values
from the first sentence to the second sentence including the insert_exists conflict.

The new format looks like:

LOG: xxx
DETAIL: Key %s; existing local tuple %s; remote new tuple %s; replica identity %s

The Key will include the conflicting key for xxx_exists conflicts. And the replica identity part
will include the replica identity keys or the full tuple value in replica identity FULL case.

> 
> 2. Similar to above, the remote tuple is not displayed in
> delete_missing but displayed in updated_missing type of conflict. If
> we follow the style mentioned in the previous point then the DETAIL
> message: "DETAIL:  Did not find the row containing (c1)=(1) to be
> updated." can also be changed to: "DETAIL:  Could not find the row to
> be updated." followed by other detail.

Same as above.


> 3. The detail of insert_exists is confusing.
> 
> ERROR:  conflict detected on relation "public.t1": conflict=insert_exists
> DETAIL:  Key (c1)=(1) already exists in unique index "t1_pkey", which
> was modified locally in transaction 802 at 2024-08-12
> 11:11:31.252148+05:30.
> 
> It sounds like the key value "(c1)=(1)" in the index is modified. How
> about changing slightly as: "Key (c1)=(1) already exists in unique
> index "t1_pkey", modified locally in transaction 802 at 2024-08-12
> 11:11:31.252148+05:30."? Feel free to propose if anything better comes
> to your mind.

The suggested message looks good to me.

> 
> 4.
> if (localorigin == InvalidRepOriginId)
> + appendStringInfo(&err_detail, _("Deleting the row containing %s that
> was modified by locally in transaction %u at %s."),
> + val_desc, localxmin, timestamptz_to_str(localts));
> 
> Typo in the above message. /modified by locally/modified locally

Fixed.

> 
> 5.
> @@ -2661,6 +2662,29 @@ apply_handle_update_internal(ApplyExecutionData
> *edata,
> {
> ...
> found = FindReplTupleInLocalRel(edata, localrel,
> &relmapentry->remoterel,
> localindexoid,
> remoteslot, &localslot);
> ...
> ...
> +
> + ReportApplyConflict(LOG, CT_UPDATE_DIFFER, relinfo,
> + GetRelationIdentityOrPK(localrel),
> 
> To find the tuple, we may have used an index other than Replica
> Identity or PK (see IsIndexUsableForReplicaIdentityFull), but while
> reporting conflict we don't consider such an index. I think the reason
> is that such an index scan wouldn't have resulted in a unique tuple
> and that is why we always compare the complete tuple in such cases. Is
> that the reason? Can we write a comment to make it clear?

Added comments atop of ReportApplyConflict for the 'indexoid' parameter.

> 
> 6.
> void ReportApplyConflict(int elevel, ConflictType type,
> + ResultRelInfo *relinfo, Oid indexoid,
> + TransactionId localxmin,
> + RepOriginId localorigin,
> + TimestampTz localts,
> + TupleTableSlot *searchslot,
> + TupleTableSlot *localslot,
> + TupleTableSlot *remoteslot,
> + EState *estate);
> 
> The prototype looks odd with pointers and non-pointer variables in
> mixed order. How about arranging parameters in the following order:
> Estate, ResultRelInfo, TupleTableSlot *searchslot, TupleTableSlot
> *localslot, TupleTableSlot *remoteslot, Oid indexoid, TransactionId
> localxmin, RepOriginId localorigin, TimestampTz localts?
> 
> 7. Like above, check the parameters of other functions like
> errdetail_apply_conflict, build_index_value_desc,
> build_tuple_value_details, etc.

Changed as suggested.

Here is V13 patch set which addressed above comments.

Best Regards,
Hou zj

Attachment

v13-0001-Detect-and-log-conflicts-in-logical-replication.patch

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

13 August 2024, 11:03:43

On Tue, Aug 13, 2024 at 10:09 AM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Here is V13 patch set which addressed above comments.
>

1.
+ReportApplyConflict(int elevel, ConflictType type, EState *estate,
+ ResultRelInfo *relinfo,

The change looks better but it would still be better to keep elevel
and type after relinfo. The same applies to other places as well.

2.
+ * The caller should ensure that the index with the OID 'indexoid' is locked.
+ *
+ * Refer to errdetail_apply_conflict for the content that will be included in
+ * the DETAIL line.
+ */
+void
+ReportApplyConflict(int elevel, ConflictType type, EState *estate,

Is it possible to add an assert to ensure that the index is locked by
the caller?

3.
+static char *
+build_tuple_value_details(EState *estate, ResultRelInfo *relinfo,
+   TupleTableSlot *searchslot,
+   TupleTableSlot *localslot,
+   TupleTableSlot *remoteslot,
+   Oid indexoid)
{
...
...
+ /*
+ * If 'searchslot' is NULL and 'indexoid' is valid, it indicates that we
+ * are reporting the unique constraint violation conflict, in which case
+ * the conflicting key values will be reported.
+ */
+ if (OidIsValid(indexoid) && !searchslot)
+ {
...
...
}

This indirect way of inferencing constraint violation looks fragile.
The caller should pass the required information explicitly and then
you can have the required assertions here.

Apart from the above, I have made quite a few changes in the code
comments and LOG messages in the attached.

--
With Regards,
Amit Kapila.

Attachment

v13_detect_conflict_amit.1.patch.txt

Re: Conflict detection and logging in logical replication

From

Michail Nikolaev

Date:

13 August 2024, 11:32:33

Hello!

> I think this is an independent issue which can be discussed separately in the
> original thread[1], and I have replied to that thread.

Thanks! But it seems like this part is still relevant to the current thread:

> It also seems possible that a conflict could be resolved by a concurrent update
> before the call to CheckAndReportConflict, which means there's no guarantee
> that the conflict will be reported correctly. Should we be concerned about
> this?

Best regards,

Mikhail.

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

14 August 2024, 02:31:10

On Tuesday, August 13, 2024 7:33 PM Michail Nikolaev <michail.nikolaev@gmail.com>  wrote:

> I think this is an independent issue which can be discussed separately in the
> original thread[1], and I have replied to that thread.

>Thanks! But it seems like this part is still relevant to the current thread:

> > It also seems possible that a conflict could be resolved by a concurrent update
> > before the call to CheckAndReportConflict, which means there's no guarantee
> > that the conflict will be reported correctly. Should we be concerned about
> > this?

This is as expected, and we have documented this in the code comments. We don't
need to report a conflict if the conflicting tuple has been removed or updated
due to concurrent transaction. The same is true if the transaction that
inserted the conflicting tuple is rolled back before CheckAndReportConflict().
We don't consider such cases as a conflict.

Best Regards,
Hou zj

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

14 August 2024, 02:35:34

On Tuesday, August 13, 2024 7:04 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Tue, Aug 13, 2024 at 10:09 AM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > Here is V13 patch set which addressed above comments.
> >
> 
> 1.
> +ReportApplyConflict(int elevel, ConflictType type, EState *estate,
> +ResultRelInfo *relinfo,
> 
> The change looks better but it would still be better to keep elevel and type after
> relinfo. The same applies to other places as well.

Changed.

> 
> 2.
> + * The caller should ensure that the index with the OID 'indexoid' is locked.
> + *
> + * Refer to errdetail_apply_conflict for the content that will be
> +included in
> + * the DETAIL line.
> + */
> +void
> +ReportApplyConflict(int elevel, ConflictType type, EState *estate,
> 
> Is it possible to add an assert to ensure that the index is locked by the caller?

Added.

> 
> 3.
> +static char *
> +build_tuple_value_details(EState *estate, ResultRelInfo *relinfo,
> +   TupleTableSlot *searchslot,
> +   TupleTableSlot *localslot,
> +   TupleTableSlot *remoteslot,
> +   Oid indexoid)
> {
> ...
> ...
> + /*
> + * If 'searchslot' is NULL and 'indexoid' is valid, it indicates that
> + we
> + * are reporting the unique constraint violation conflict, in which
> + case
> + * the conflicting key values will be reported.
> + */
> + if (OidIsValid(indexoid) && !searchslot) {
> ...
> ...
> }
> 
> This indirect way of inferencing constraint violation looks fragile.
> The caller should pass the required information explicitly and then you can
> have the required assertions here.
> 
> Apart from the above, I have made quite a few changes in the code comments
> and LOG messages in the attached.

Thanks. I have addressed above comments and merged the changes.

Here is the V14 patch.

Best Regards,
Hou zj

Attachment

v14-0001-Detect-and-log-conflicts-in-logical-replication.patch

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

14 August 2024, 11:01:56

On Wed, Aug 14, 2024 at 8:05 AM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Here is the V14 patch.
>

Review comments:
1.
ReportApplyConflict()
{
...
+ ereport(elevel,
+ errcode(ERRCODE_INTEGRITY_CONSTRAINT_VIOLATION),
+ errmsg("conflict detected on relation \"%s.%s\": conflict=%s",
+    get_namespace_name(RelationGetNamespace(localrel)),
...

Is it a good idea to use ERRCODE_INTEGRITY_CONSTRAINT_VIOLATION for
all conflicts? I think it is okay to use for insert_exists and
update_exists. The other error codes to consider for conflicts other
than insert_exists and update_exists are
ERRCODE_T_R_SERIALIZATION_FAILURE, ERRCODE_CARDINALITY_VIOLATION,
ERRCODE_NO_DATA, ERRCODE_NO_DATA_FOUND,
ERRCODE_TRIGGERED_DATA_CHANGE_VIOLATION,
ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE.

BTW, even for insert/update_exists, won't it better to use
ERRCODE_UNIQUE_VIOLATION?

2.
+build_tuple_value_details()
{
...
+ if (searchslot)
+ {
+ /*
+ * If a valid index OID is provided, build the replica identity key
+ * value string. Otherwise, construct the full tuple value for REPLICA
+ * IDENTITY FULL cases.
+ */

AFAICU, this can't happen for insert/update_exists. If so, we should
add an assert for those two conflict types.

3.
+build_tuple_value_details()
{
...
+    /*
+     * Although logical replication doesn't maintain the bitmap for the
+     * columns being inserted, we still use it to create 'modifiedCols'
+     * for consistency with other calls to ExecBuildSlotValueDescription.
+     */
+    modifiedCols = bms_union(ExecGetInsertedCols(relinfo, estate),
+                 ExecGetUpdatedCols(relinfo, estate));
+    desc = ExecBuildSlotValueDescription(relid, remoteslot, tupdesc,
+                       modifiedCols, 64);

Can we mention in the comments the reason for not including generated columns?

Apart from the above, the attached contains some cosmetic changes.

--
With Regards,
Amit Kapila.

Attachment

v14_conflict_detect_amit.1.patch.txt

Re: Conflict detection and logging in logical replication

From

Michail Nikolaev

Date:

14 August 2024, 17:15:10

Hello, Hou!

> This is as expected, and we have documented this in the code comments. We don't
> need to report a conflict if the conflicting tuple has been removed or updated
> due to concurrent transaction. The same is true if the transaction that
> inserted the conflicting tuple is rolled back before CheckAndReportConflict().
> We don't consider such cases as a conflict.

That seems a little bit strange to me.

From the perspective of a user, I expect that if a change from publisher is not applied - I need to know about it from the logs.
But in that case, I will not see any information about conflict in the logs in SOME cases. But in OTHER cases I will see it.
However, in both cases the change from publisher was not applied.
And these cases are just random and depend on the timing of race conditions. It is not something I am expecting from the database.

Maybe it is better to report about the fact that event from publisher was not applied because of conflict and then try to
provide additional information about the conflict itself?

Or possibly in case we were unable to apply the event and not able to find the conflict, we should retry the event processing?
Especially, this seems to be a good idea with future [1] in mind.

Or we may add ExecInsertIndexTuples ability to return information about conflicts (or ItemPointer of conflicting tuple) and then

report about the conflict in a more consistent way?

Best regards,
Mikhail.

[1]: https://commitfest.postgresql.org/49/5021/

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

15 August 2024, 10:18:42

On Wednesday, August 14, 2024 10:15 PM Michail Nikolaev <michail.nikolaev@gmail.com>  wrote:
> > This is as expected, and we have documented this in the code comments. We don't
> > need to report a conflict if the conflicting tuple has been removed or updated
> > due to concurrent transaction. The same is true if the transaction that
> > inserted the conflicting tuple is rolled back before CheckAndReportConflict().
> > We don't consider such cases as a conflict.
> 
> That seems a little bit strange to me.
> 
> From the perspective of a user, I expect that if a change from publisher is not
> applied - I need to know about it from the logs. 

I think this is exactly the current behavior in the patch. In the race
condition we discussed, the insert will be applied if the conflicting tuple is
removed concurrently before CheckAndReportConflict().

> But in that case, I will not see any information about conflict in the logs
> in SOME cases. But in OTHER cases I will see it. However, in both cases the
> change from publisher was not applied. And these cases are just random and
> depend on the timing of race conditions. It is not something I am expecting
> from the database.

I think you might misunderstand the behavior of CheckAndReportConflict(), even
if it found a conflict, it still inserts the tuple into the index which means
the change is anyway applied.

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

16 August 2024, 07:23:25

On Wed, Aug 14, 2024 at 7:45 PM Michail Nikolaev
<michail.nikolaev@gmail.com> wrote:
>
> > This is as expected, and we have documented this in the code comments. We don't
> > need to report a conflict if the conflicting tuple has been removed or updated
> > due to concurrent transaction. The same is true if the transaction that
> > inserted the conflicting tuple is rolled back before CheckAndReportConflict().
> > We don't consider such cases as a conflict.
>
> That seems a little bit strange to me.
>
> From the perspective of a user, I expect that if a change from publisher is not applied - I need to know about it
fromthe logs. 
>

In the above conditions where a concurrent tuple insertion is removed
or rolled back before CheckAndReportConflict, the tuple inserted by
apply will remain. There is no need to report anything in such cases
as apply was successful.

> But in that case, I will not see any information about conflict in the logs in SOME cases. But in OTHER cases I will
seeit. 
> However, in both cases the change from publisher was not applied.
> And these cases are just random and depend on the timing of race conditions. It is not something I am expecting from
thedatabase. 
>
> Maybe it is better to report about the fact that event from publisher was not applied because of conflict and then
tryto 
> provide additional information about the conflict itself?
>
> Or possibly in case we were unable to apply the event and not able to find the conflict, we should retry the event
processing?
>

Per my understanding, we will apply or the conflict will be logged and
retried where required (unique key violation).

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

16 August 2024, 08:16:43

On Thu, Aug 15, 2024 at 12:47 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Thanks. I have checked and merged the changes. Here is the V15 patch
> which addressed above comments.

Thanks for the patch. Please find few comments and queries:

1)
For various conflicts , we have these in Logs:
Replica identity (val1)=(30).                (for RI on 1 column)
Replica identity (pk, val1)=(200, 20).  (for RI on  2 columns)
Replica identity (40, 40, 11).                (for RI full)

Shall we have have column list in last case as well, or can simply
have *full* keyword i.e. Replica identity full (40, 40, 11)

2)
For toast column, we dump null in remote-tuple. I know that the toast
column is not sent in  new-tuple from the publisher and thus the
behaviour, but it could be misleading for users. Perhaps document
this?

See 'null' in all these examples in  remote tuple:

update_differ With PK:
LOG:  conflict detected on relation "public.t1": conflict=update_differ
DETAIL:  Updating the row that was modified locally in transaction 831
at 2024-08-16 09:59:26.566012+05:30.
Existing local tuple (30, 30, 30,
yyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyyy...);
remote tuple (30, 30, 300, null); replica identity (pk, val1)=(30,
30).

update_missing With PK:
LOG:  conflict detected on relation "public.t1": conflict=update_missing
DETAIL:  Could not find the row to be updated.
Remote tuple (10, 10, 100, null); replica identity (pk, val1)=(10, 10).

update_missing with RI full:
LOG:  conflict detected on relation "public.t1": conflict=update_missing
DETAIL:  Could not find the row to be updated.
Remote tuple (20, 20, 2000, null); replica identity (20, 20, 10,
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx...).

3)
For update_exists(), we dump:
Key (a, b)=(2, 1)

For delete_missing, update_missing, update_differ, we dump:
Replica identity (a, b)=(2, 1).

For update_exists as well, shouldn't we dump 'Replica identity'? Only
for insert case, it should be referred as 'Key'.

4)
Why delete_missing is not having remote_tuple. Is it because we dump
new tuple as 'remote tuple', which is not relevant for delete_missing?
2024-08-16 09:13:33.174 IST [419839] LOG:  conflict detected on
relation "public.t1": conflict=delete_missing
2024-08-16 09:13:33.174 IST [419839] DETAIL:  Could not find the row
to be deleted.
Replica identity (val1)=(30).

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

16 August 2024, 09:18:14

On Fri, Aug 16, 2024 at 10:46 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> 3)
> For update_exists(), we dump:
> Key (a, b)=(2, 1)
>
> For delete_missing, update_missing, update_differ, we dump:
> Replica identity (a, b)=(2, 1).
>
> For update_exists as well, shouldn't we dump 'Replica identity'? Only
> for insert case, it should be referred as 'Key'.
>

On rethinking, is it because for update_exists case 'Key' dumped is
not the one used to search the row to be updated? Instead it is the
one used to search the conflicting row. Unlike update_differ, the row
to be updated and the row currently conflicting will be different for
update_exists case. I earlier thought that 'KEY' and 'Existing local
tuple' dumped always belong to the row currently being
updated/deleted/inserted. But for 'update_eixsts', that is not the
case. We are dumping 'Existing local tuple' and 'Key' for the row
which is conflicting and not the one being updated.  Example:

ERROR:  conflict detected on relation "public.tab_1": conflict=update_exists
Key (a, b)=(2, 1); existing local tuple (2, 1); remote tuple (2, 1).

Operations performed were:
Pub: insert into tab values (1,1);
Sub: insert into tab values (2,1);
Pub: update tab set a=2 where a=1;

Here Key and local tuple are both 2,1 instead of 1,1. While replica
identity value (used to search original row) will be 1,1 only.

It may be slightly confusing or say tricky to understand when compared
to other conflicts' LOGs. But not sure what better we can do here.

--------------------

One more comment:

5)
For insert/update_exists, the sequence is:
Key .. ; existing local tuple .. ; remote tuple ...

For rest of the conflicts, sequence is:
 Existing local tuple .. ; remote tuple .. ; replica identity ..

Is it intentional? Shall the 'Key' or 'Replica Identity' be the first
one to come in all conflicts?

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

16 August 2024, 09:31:10

On Fri, Aug 16, 2024 at 10:46 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Thu, Aug 15, 2024 at 12:47 PM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > Thanks. I have checked and merged the changes. Here is the V15 patch
> > which addressed above comments.
>
> Thanks for the patch. Please find few comments and queries:
>
> 1)
> For various conflicts , we have these in Logs:
> Replica identity (val1)=(30).                (for RI on 1 column)
> Replica identity (pk, val1)=(200, 20).  (for RI on  2 columns)
> Replica identity (40, 40, 11).                (for RI full)
>
> Shall we have have column list in last case as well, or can simply
> have *full* keyword i.e. Replica identity full (40, 40, 11)
>

I would prefer 'full' instead of the entire column list as the
complete column list could be long and may not much sense.

>
> 2)
> For toast column, we dump null in remote-tuple. I know that the toast
> column is not sent in  new-tuple from the publisher and thus the
> behaviour, but it could be misleading for users. Perhaps document
> this?
>

Agreed that we should document this. I suggest that we can have a doc
patch that explains the conflict logging format and in that, we can
mention this behavior as well.

> 3)
> For update_exists(), we dump:
> Key (a, b)=(2, 1)
>
> For delete_missing, update_missing, update_differ, we dump:
> Replica identity (a, b)=(2, 1).
>
> For update_exists as well, shouldn't we dump 'Replica identity'? Only
> for insert case, it should be referred as 'Key'.
>

I think update_exists is quite similar to insert_exists and both
happen due to unique key violation. So, it seems okay to display the
Key for update_exists.

>
> 4)
> Why delete_missing is not having remote_tuple. Is it because we dump
> new tuple as 'remote tuple', which is not relevant for delete_missing?
>

Right.

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

16 August 2024, 09:49:14

On Fri, Aug 16, 2024 at 11:48 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Fri, Aug 16, 2024 at 10:46 AM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > 3)
> > For update_exists(), we dump:
> > Key (a, b)=(2, 1)
> >
> > For delete_missing, update_missing, update_differ, we dump:
> > Replica identity (a, b)=(2, 1).
> >
> > For update_exists as well, shouldn't we dump 'Replica identity'? Only
> > for insert case, it should be referred as 'Key'.
> >
>
> On rethinking, is it because for update_exists case 'Key' dumped is
> not the one used to search the row to be updated? Instead it is the
> one used to search the conflicting row. Unlike update_differ, the row
> to be updated and the row currently conflicting will be different for
> update_exists case. I earlier thought that 'KEY' and 'Existing local
> tuple' dumped always belong to the row currently being
> updated/deleted/inserted. But for 'update_eixsts', that is not the
> case. We are dumping 'Existing local tuple' and 'Key' for the row
> which is conflicting and not the one being updated.  Example:
>
> ERROR:  conflict detected on relation "public.tab_1": conflict=update_exists
> Key (a, b)=(2, 1); existing local tuple (2, 1); remote tuple (2, 1).
>
> Operations performed were:
> Pub: insert into tab values (1,1);
> Sub: insert into tab values (2,1);
> Pub: update tab set a=2 where a=1;
>
> Here Key and local tuple are both 2,1 instead of 1,1. While replica
> identity value (used to search original row) will be 1,1 only.
>
> It may be slightly confusing or say tricky to understand when compared
> to other conflicts' LOGs. But not sure what better we can do here.
>

The update_exists behaves more like insert_exists as we detect that
only while inserting into index. It is also not clear to me if we can
do better than to clarify this in docs.

> --------------------
>
> One more comment:
>
> 5)
> For insert/update_exists, the sequence is:
> Key .. ; existing local tuple .. ; remote tuple ...
>
> For rest of the conflicts, sequence is:
>  Existing local tuple .. ; remote tuple .. ; replica identity ..
>
> Is it intentional? Shall the 'Key' or 'Replica Identity' be the first
> one to come in all conflicts?
>

This is worth considering but Replica Identity signifies the old tuple
values, that is why it is probably kept at the end. But let's see what
Hou-San or others think about this.

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

16 August 2024, 12:24:41

On Fri, Aug 16, 2024 at 12:19 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Fri, Aug 16, 2024 at 11:48 AM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > On Fri, Aug 16, 2024 at 10:46 AM shveta malik <shveta.malik@gmail.com> wrote:
> > >
> > > 3)
> > > For update_exists(), we dump:
> > > Key (a, b)=(2, 1)
> > >
> > > For delete_missing, update_missing, update_differ, we dump:
> > > Replica identity (a, b)=(2, 1).
> > >
> > > For update_exists as well, shouldn't we dump 'Replica identity'? Only
> > > for insert case, it should be referred as 'Key'.
> > >
> >
> > On rethinking, is it because for update_exists case 'Key' dumped is
> > not the one used to search the row to be updated? Instead it is the
> > one used to search the conflicting row. Unlike update_differ, the row
> > to be updated and the row currently conflicting will be different for
> > update_exists case. I earlier thought that 'KEY' and 'Existing local
> > tuple' dumped always belong to the row currently being
> > updated/deleted/inserted. But for 'update_eixsts', that is not the
> > case. We are dumping 'Existing local tuple' and 'Key' for the row
> > which is conflicting and not the one being updated.  Example:
> >
> > ERROR:  conflict detected on relation "public.tab_1": conflict=update_exists
> > Key (a, b)=(2, 1); existing local tuple (2, 1); remote tuple (2, 1).
> >
> > Operations performed were:
> > Pub: insert into tab values (1,1);
> > Sub: insert into tab values (2,1);
> > Pub: update tab set a=2 where a=1;
> >
> > Here Key and local tuple are both 2,1 instead of 1,1. While replica
> > identity value (used to search original row) will be 1,1 only.
> >
> > It may be slightly confusing or say tricky to understand when compared
> > to other conflicts' LOGs. But not sure what better we can do here.
> >
>
> The update_exists behaves more like insert_exists as we detect that
> only while inserting into index. It is also not clear to me if we can
> do better than to clarify this in docs.
>

Instead of 'existing local tuple', will it be slightly better to have
'conflicting local tuple'?

Few trivial comments:

1)
errdetail_apply_conflict() header says:

 * 2. Display of conflicting key, existing local tuple, remote new tuple, and
 *    replica identity columns,  if any.

We may mention that existing *conflicting* local tuple.

Looking at build_tuple_value_details(), the cases where we display
'KEY 'and the ones where we display 'replica identity' are mutually
exclusives (we have ASSERTs like that).  Shall we add this info in
header that either Key or   'replica identity' is displayed. Or if we
don't want to make it mutually exclusive then update_exists is one
such casw where we can have both Key and 'Replica Identity cols'.


2)
BuildIndexValueDescription() header comment says:

 * This is currently used
 * for building unique-constraint, exclusion-constraint and logical replication
 * tuple missing conflict error messages

Is it being used only for 'tuple missing conflict' flow? I thought, it
will be hit for other flows as well.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Michail Nikolaev

Date:

16 August 2024, 14:46:45

Hello!

> I think you might misunderstand the behavior of CheckAndReportConflict(), even
> if it found a conflict, it still inserts the tuple into the index which means
> the change is anyway applied.

> In the above conditions where a concurrent tuple insertion is removed
> or rolled back before CheckAndReportConflict, the tuple inserted by
> apply will remain. There is no need to report anything in such cases
> as apply was successful.

Yes, thank you for explanation, I was thinking UNIQUE_CHECK_PARTIAL works differently.

But now I think DirtySnapshot-related bug is a blocker for this feature then, I'll reply into original after rechecking it.

Best regards,

Mikhail.

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

18 August 2024, 11:49:12

On Friday, August 16, 2024 2:31 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> On Fri, Aug 16, 2024 at 10:46 AM shveta malik <shveta.malik@gmail.com>
> wrote:
> >
> > On Thu, Aug 15, 2024 at 12:47 PM Zhijie Hou (Fujitsu)
> > <houzj.fnst@fujitsu.com> wrote:
> > >
> > > Thanks. I have checked and merged the changes. Here is the V15 patch
> > > which addressed above comments.
> >
> > Thanks for the patch. Please find few comments and queries:
> >
> > 1)
> > For various conflicts , we have these in Logs:
> > Replica identity (val1)=(30).                (for RI on 1 column)
> > Replica identity (pk, val1)=(200, 20).  (for RI on  2 columns)
> > Replica identity (40, 40, 11).                (for RI full)
> >
> > Shall we have have column list in last case as well, or can simply
> > have *full* keyword i.e. Replica identity full (40, 40, 11)
> >
> 
> I would prefer 'full' instead of the entire column list as the complete column list
> could be long and may not much sense.

+1 and will change in V16 patch.

Best Regards,
Hou zj

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

18 August 2024, 11:49:37

On Friday, August 16, 2024 2:49 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> 
> 
> > --------------------
> >
> > One more comment:
> >
> > 5)
> > For insert/update_exists, the sequence is:
> > Key .. ; existing local tuple .. ; remote tuple ...
> >
> > For rest of the conflicts, sequence is:
> >  Existing local tuple .. ; remote tuple .. ; replica identity ..
> >
> > Is it intentional? Shall the 'Key' or 'Replica Identity' be the first
> > one to come in all conflicts?
> >
> 
> This is worth considering but Replica Identity signifies the old tuple values,
> that is why it is probably kept at the end. 

Right. I personally think the current position is ok.

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

19 August 2024, 06:37:51

On Sun, Aug 18, 2024 at 2:27 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Attach the V16 patch which addressed the comments we agreed on.
> I will add a doc patch to explain the log format after the 0001 is RFC.
>

Thank You for addressing comments. Please see this scenario:

create table tab1(pk int primary key, val1 int unique, val2 int);

pub: insert into tab1 values(1,1,1);
sub: insert into tab1 values(2,2,3);
pub: update tab1 set val1=2 where pk=1;

Wrong 'replica identity' column logged? shouldn't it be pk?

ERROR:  conflict detected on relation "public.tab1": conflict=update_exists
DETAIL:  Key already exists in unique index "tab1_val1_key", modified
locally in transaction 801 at 2024-08-19 08:50:47.974815+05:30.
Key (val1)=(2); existing local tuple (2, 2, 3); remote tuple (1, 2,
1); replica identity (val1)=(1).

thanks
Shveta

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

19 August 2024, 06:38:47

On Friday, August 16, 2024 7:47 PM Michail Nikolaev <michail.nikolaev@gmail.com>  wrote:
> > I think you might misunderstand the behavior of CheckAndReportConflict(),
> > even if it found a conflict, it still inserts the tuple into the index which
> > means the change is anyway applied.
> 
> > In the above conditions where a concurrent tuple insertion is removed or
> > rolled back before CheckAndReportConflict, the tuple inserted by apply will
> > remain. There is no need to report anything in such cases as apply was
> > successful.
> 
> Yes, thank you for explanation, I was thinking UNIQUE_CHECK_PARTIAL works
> differently.
> 
> But now I think DirtySnapshot-related bug is a blocker for this feature then,
> I'll reply into original after rechecking it.

Based on your response in the original thread[1], where you confirmed that the
dirty snapshot bug does not impact the detection of insert_exists conflicts, I
assume we are in agreement that this bug is not a blocker for the detection
feature. If you think otherwise, please feel free to let me know.

[1]
https://www.postgresql.org/message-id/CANtu0oh69b%2BVCiASX86dF_eY%3D9%3DA2RmMQ_%2B0%2BuxZ_Zir%2BoNhhw%40mail.gmail.com

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

19 August 2024, 07:49:43

On Mon, Aug 19, 2024 at 9:07 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Sun, Aug 18, 2024 at 2:27 PM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > Attach the V16 patch which addressed the comments we agreed on.
> > I will add a doc patch to explain the log format after the 0001 is RFC.
> >
>
> Thank You for addressing comments. Please see this scenario:
>
> create table tab1(pk int primary key, val1 int unique, val2 int);
>
> pub: insert into tab1 values(1,1,1);
> sub: insert into tab1 values(2,2,3);
> pub: update tab1 set val1=2 where pk=1;
>
> Wrong 'replica identity' column logged? shouldn't it be pk?
>
> ERROR:  conflict detected on relation "public.tab1": conflict=update_exists
> DETAIL:  Key already exists in unique index "tab1_val1_key", modified
> locally in transaction 801 at 2024-08-19 08:50:47.974815+05:30.
> Key (val1)=(2); existing local tuple (2, 2, 3); remote tuple (1, 2,
> 1); replica identity (val1)=(1).

Apart from this one, I have no further comments on v16.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

19 August 2024, 09:07:44

On Mon, Aug 19, 2024 at 9:08 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Sun, Aug 18, 2024 at 2:27 PM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > Attach the V16 patch which addressed the comments we agreed on.
> > I will add a doc patch to explain the log format after the 0001 is RFC.
> >
>
> Thank You for addressing comments. Please see this scenario:
>
> create table tab1(pk int primary key, val1 int unique, val2 int);
>
> pub: insert into tab1 values(1,1,1);
> sub: insert into tab1 values(2,2,3);
> pub: update tab1 set val1=2 where pk=1;
>
> Wrong 'replica identity' column logged? shouldn't it be pk?
>
> ERROR:  conflict detected on relation "public.tab1": conflict=update_exists
> DETAIL:  Key already exists in unique index "tab1_val1_key", modified
> locally in transaction 801 at 2024-08-19 08:50:47.974815+05:30.
> Key (val1)=(2); existing local tuple (2, 2, 3); remote tuple (1, 2,
> 1); replica identity (val1)=(1).
>

The docs say that by default replica identity is primary_key [1] (see
REPLICA IDENTITY), [2] (see pg_class.relreplident). So, using the same
format to display PK seems reasonable. I don't think adding additional
code to distinguish these two cases in the LOG message is worth it. We
can always change such things later if that is what users and or
others prefer.

[1] - https://www.postgresql.org/docs/devel/sql-altertable.html
[2] - https://www.postgresql.org/docs/devel/catalog-pg-class.html

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

19 August 2024, 09:23:50

On Mon, Aug 19, 2024 at 11:37 AM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Mon, Aug 19, 2024 at 9:08 AM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > On Sun, Aug 18, 2024 at 2:27 PM Zhijie Hou (Fujitsu)
> > <houzj.fnst@fujitsu.com> wrote:
> > >
> > > Attach the V16 patch which addressed the comments we agreed on.
> > > I will add a doc patch to explain the log format after the 0001 is RFC.
> > >
> >
> > Thank You for addressing comments. Please see this scenario:
> >
> > create table tab1(pk int primary key, val1 int unique, val2 int);
> >
> > pub: insert into tab1 values(1,1,1);
> > sub: insert into tab1 values(2,2,3);
> > pub: update tab1 set val1=2 where pk=1;
> >
> > Wrong 'replica identity' column logged? shouldn't it be pk?
> >
> > ERROR:  conflict detected on relation "public.tab1": conflict=update_exists
> > DETAIL:  Key already exists in unique index "tab1_val1_key", modified
> > locally in transaction 801 at 2024-08-19 08:50:47.974815+05:30.
> > Key (val1)=(2); existing local tuple (2, 2, 3); remote tuple (1, 2,
> > 1); replica identity (val1)=(1).
> >
>
> The docs say that by default replica identity is primary_key [1] (see
> REPLICA IDENTITY),

yes, I agree. But here the importance of dumping it was to know the
value of RI as well which is being used as an identification of row
being updated rather than row being conflicted. Value is logged
correctly.

>[2] (see pg_class.relreplident). So, using the same
> format to display PK seems reasonable. I don't think adding additional
> code to distinguish these two cases in the LOG message is worth it.

I don't see any additional code added for this case except getting an
existing logic being used for update_exists.

>We
> can always change such things later if that is what users and or
> others prefer.
>

Sure, if fixing this issue (where we are reporting the wrong col name)
needs additional logic, then I am okay to skip it for the time being.
We can address later if/when needed.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

19 August 2024, 09:39:43

On Mon, Aug 19, 2024 at 11:54 AM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Mon, Aug 19, 2024 at 11:37 AM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Mon, Aug 19, 2024 at 9:08 AM shveta malik <shveta.malik@gmail.com> wrote:
> > >
> > > On Sun, Aug 18, 2024 at 2:27 PM Zhijie Hou (Fujitsu)
> > > <houzj.fnst@fujitsu.com> wrote:
> > > >
> > > > Attach the V16 patch which addressed the comments we agreed on.
> > > > I will add a doc patch to explain the log format after the 0001 is RFC.
> > > >
> > >
> > > Thank You for addressing comments. Please see this scenario:
> > >
> > > create table tab1(pk int primary key, val1 int unique, val2 int);
> > >
> > > pub: insert into tab1 values(1,1,1);
> > > sub: insert into tab1 values(2,2,3);
> > > pub: update tab1 set val1=2 where pk=1;
> > >
> > > Wrong 'replica identity' column logged? shouldn't it be pk?
> > >
> > > ERROR:  conflict detected on relation "public.tab1": conflict=update_exists
> > > DETAIL:  Key already exists in unique index "tab1_val1_key", modified
> > > locally in transaction 801 at 2024-08-19 08:50:47.974815+05:30.
> > > Key (val1)=(2); existing local tuple (2, 2, 3); remote tuple (1, 2,
> > > 1); replica identity (val1)=(1).
> > >
> >
> > The docs say that by default replica identity is primary_key [1] (see
> > REPLICA IDENTITY),
>
> yes, I agree. But here the importance of dumping it was to know the
> value of RI as well which is being used as an identification of row
> being updated rather than row being conflicted. Value is logged
> correctly.
>

Agreed, sorry, I misunderstood the problem reported. I thought the
suggestion was to use 'primary key' instead of 'replica identity' but
you pointed out that the column used in 'replica identity' was wrong.
We should fix this one.

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

19 August 2024, 10:03:04

On Mon, Aug 19, 2024 at 12:09 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Mon, Aug 19, 2024 at 11:54 AM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > On Mon, Aug 19, 2024 at 11:37 AM Amit Kapila <amit.kapila16@gmail.com> wrote:
> > >
> > > On Mon, Aug 19, 2024 at 9:08 AM shveta malik <shveta.malik@gmail.com> wrote:
> > > >
> > > > On Sun, Aug 18, 2024 at 2:27 PM Zhijie Hou (Fujitsu)
> > > > <houzj.fnst@fujitsu.com> wrote:
> > > > >
> > > > > Attach the V16 patch which addressed the comments we agreed on.
> > > > > I will add a doc patch to explain the log format after the 0001 is RFC.
> > > > >
> > > >
> > > > Thank You for addressing comments. Please see this scenario:
> > > >
> > > > create table tab1(pk int primary key, val1 int unique, val2 int);
> > > >
> > > > pub: insert into tab1 values(1,1,1);
> > > > sub: insert into tab1 values(2,2,3);
> > > > pub: update tab1 set val1=2 where pk=1;
> > > >
> > > > Wrong 'replica identity' column logged? shouldn't it be pk?
> > > >
> > > > ERROR:  conflict detected on relation "public.tab1": conflict=update_exists
> > > > DETAIL:  Key already exists in unique index "tab1_val1_key", modified
> > > > locally in transaction 801 at 2024-08-19 08:50:47.974815+05:30.
> > > > Key (val1)=(2); existing local tuple (2, 2, 3); remote tuple (1, 2,
> > > > 1); replica identity (val1)=(1).
> > > >
> > >
> > > The docs say that by default replica identity is primary_key [1] (see
> > > REPLICA IDENTITY),
> >
> > yes, I agree. But here the importance of dumping it was to know the
> > value of RI as well which is being used as an identification of row
> > being updated rather than row being conflicted. Value is logged
> > correctly.
> >
>
> Agreed, sorry, I misunderstood the problem reported.

no problem.

>I thought the
> suggestion was to use 'primary key' instead of 'replica identity' but
> you pointed out that the column used in 'replica identity' was wrong.
> We should fix this one.
>

Yes, that is what I pointed out. But let me remind you that this logic
to display both 'Key' and 'RI' is done in the latest patch. Earlier
either 'Key' or 'RI' was logged. But since for 'update_exists', both
make sense, thus I suggested to dump both. 'RI' column is dumped
correctly in all other cases, except this new one. So if fixing this
wrong column name for update_exists adds more complexity, then I am
okay with skipping the 'RI' dump for this case. We’re fine with just
'Key' for now, and we can address this later.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

19 August 2024, 12:33:03

On Mon, Aug 19, 2024 at 12:32 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
>
> Thanks for reporting the bug. I have fixed it and ran pgindent in V17 patch.
> I also adjusted few comments and fixed a typo.
>

Thanks for the patch. Re-tested it, all scenarios seem to work well now.

I see that this version has new header inclusion in conflict.c, due to
which I think "catalog/index.h" inclusion is now redundant. Please
recheck and remove if so.
Also, there are few long lines in conflict.c (see line 408, 410).

Rest looks good.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

20 August 2024, 07:36:35

On Mon, Aug 19, 2024 at 4:16 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> > Rest looks good.
> >
>
> Thanks for the review and testing.
>

Pushed.

--
With Regards,
Amit Kapila.

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

21 August 2024, 06:05:47

On Wednesday, August 21, 2024 9:33 AM Jonathan S. Katz <jkatz@postgresql.org> wrote:
> On 8/6/24 4:15 AM, Zhijie Hou (Fujitsu) wrote:
> 
> > Thanks for the idea! I thought about few styles based on the suggested
> > format, what do you think about the following ?
> 
> Thanks for proposing formats. Before commenting on the specifics, I do want to
> ensure that we're thinking about the following for the log formats:
> 
> 1. For the PostgreSQL logs, we'll want to ensure we do it in a way that's as
> convenient as possible for people to parse the context from scripts.

Yeah. And I personally think the current log format is OK for parsing purposes.

> 
> 2. Semi-related, I still think the simplest way to surface this info to a user is
> through a "pg_stat_..." view or similar catalog mechanism (I'm less opinionated
> on the how outside of we should make it available via SQL).

We have a patch(v19-0002) in this thread to collect conflict stats and display
them in the view, and the patch is under review.

Storing it into a catalog needs more analysis as we may need to add addition
logic to clean up old conflict data in that catalog table. I think we can
consider it as a future improvement.

> 
> 3. We should ensure we're able to convey to the user these details about the
> conflict:
> 
> * What time it occurred on the local server (which we'd have in the logs)
> * What kind of conflict it is
> * What table the conflict occurred on
> * What action caused the conflict
> * How the conflict was resolved (ability to include source/origin info)

I think all above are already covered in the current conflict log. Except that
we have not support resolving the conflict, so we don't log the resolution.

> 
> 
> I think outputting the remote/local tuple value may be a parameter we need to
> think about (with the desired outcome of trying to avoid another parameter). I
> have a concern about unintentionally leaking data (and I understand that
> someone with access to the logs does have a broad ability to view data); I'm
> less concerned about the size of the logs, as conflicts in a well-designed
> system should be rare (though a conflict storm could fill up the logs, likely there
> are other issues to content with at that point).

We could use an option to control, but the tuple value is already output in some
existing cases (e.g. partition check, table constraints check, view with check
constraints, unique violation), and it would test the current user's
privileges to decide whether to output the tuple or not. So, I think it's OK
to display the tuple for conflicts.

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

21 August 2024, 06:39:32

On Tue, Aug 20, 2024 at 4:45 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Here are the remaining patches.
>
> 0001 adds additional doc to explain the log format.

Thanks for the patch. Please find few comments on 001:

1)
+<literal>Key</literal> (column_name, ...)=(column_name, ...);
existing local tuple (column_name, ...)=(column_name, ...); remote
tuple (column_name, ...)=(column_name, ...); replica identity
(column_name, ...)=(column_name, ...).

-- column_name --> column_value everywhere in right to '='?

2)
+      Note that for an
+      update operation, the column value of the new tuple may be NULL if the
+      value is unchanged.

-- Shall we mention the toast value here? In all other cases, we get a
full new tuple.

3)
+      The key section in the second sentence of the DETAIL line
includes the key values of the tuple that already exists in the local
relation for insert_exists or update_exists conflicts.

-- Shall we mention the key is the column value violating a unique
constraint? Something like this:
The key section in the second sentence of the DETAIL line includes the
key values of the local tuple that violates unique constraint for
insert_exists or update_exists conflicts.

4)
Shall we give an example LOG message in the end?

thanks
Shveta

RE: Conflict detection and logging in logical replication

From

"Hayato Kuroda (Fujitsu)"

Date:

21 August 2024, 08:30:43

Dear Hou,

Thanks for updating the patch! I think the patch is mostly good.
Here are minor comments.

0001:

01.
```
+<screen>
+LOG:  conflict detected on relation "schemaname.tablename": conflict=<literal>conflict_type</literal>
+DETAIL:  <literal>detailed explaination</literal>.
...
+</screen>
```

I don't think the label is correct. <screen> label should be used for the actual
example output, not for explaining the format. I checked several files like
amcheck.sgml and auto-exlain.sgml and func.sgml and they seemed to follow the
rule.

02.
```
+     <para>
+      The <literal>key</literal> section in the second sentence of the
...
```

I preferred that section name is quoted.

0002:

03.
```
-#include "replication/logicalrelation.h"
```

Just to confirm - this removal is not related with the feature but just the
improvement, right?


Best regards,
Hayato Kuroda
FUJITSU LIMITED

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

21 August 2024, 09:15:37

On Tue, Aug 20, 2024 at 4:45 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> Here are the remaining patches.
>
> 0001 adds additional doc to explain the log format.
> 0002 collects statistics about conflicts in logical replication.
>

0002 has not changed since I last reviewed it. It seems all my old
comments are addressed. One trivial thing:

I feel in doc, we shall mention that any of the conflicts resulting in
apply-error will be counted in both apply_error_count and the
corresponding <conflict>_count. What do you think?

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Peter Smith

Date:

21 August 2024, 09:44:42

Here are some review comments for the v19-0001 docs patch.

The content seemed reasonable, but IMO it should be presented quite differently.

~~~~

1. Use sub-sections

I expect this logical replication "Conflicts" section is going to
evolve into something much bigger. Surely, it's not going to be one
humongous page of details, so it will be a section with lots of
subsections like all the other in Chapter 29.

IMO, you should be writing the docs in that kind of structure from the
beginning.

For example, I'm thinking something like below (this is just an
example - surely lots more subsections will be needed for this topic):

29.6 Conflicts
29.6.1. Conflict types
29.6.2. Logging format
29.6.3. Examples

Specifically, this v19-0001 patch information should be put into a
subsection like the 29.6.2 shown above.

~~~

2. Markup

+<screen>
+LOG:  conflict detected on relation "schemaname.tablename":
conflict=<literal>conflict_type</literal>
+DETAIL:  <literal>detailed explaination</literal>.
+<literal>Key</literal> (column_name, ...)=(column_name, ...);
<literal>existing local tuple</literal> (column_name,
...)=(column_name, ...); <literal>remote tuple</literal> (column_name,
...)=(column_name, ...); <literal>replica identity</literal>
(column_name, ...)=(column_name, ...).
+</screen>

IMO this should be using markup more like the SQL syntax references.
- e.g. I suggest <synopsis> instead of <screen>
- e.g. I suggest all the substitution parameters (e.g. detailed
explanation, conflict_type, column_name, ...) in the log should use
<replaceable class="parameter"> and use those markups again later in
these docs instead of <literal>

~

nit - typo /explaination/explanation/

~

nit - The amount of scrolling needed makes this LOG format too hard to
see. Try to wrap it better so it can fit without being so wide.

~~~

3. Restructure the list

+   <itemizedlist>
+    <listitem>

I suggest restructuring all this to use a nested list like:

LOG
- conflict_type
DETAIL
- detailed_explanation
- key
- existing_local_tuple
- remote_tuple
- replica_identity

Doing this means you can remove a great deal of the unnecessary junk
words like "of the first sentence in the DETAIL", and "sentence of the
DETAIL line" etc. The result will be much less text but much simpler
text too.

======
Kind Regards,
Peter Smith.
Fujitsu Australia

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

21 August 2024, 12:32:23

On Wednesday, August 21, 2024 11:40 AM shveta malik <shveta.malik@gmail.com> wrote:
> 
> On Tue, Aug 20, 2024 at 4:45 PM Zhijie Hou (Fujitsu) <houzj.fnst@fujitsu.com>
> wrote:> 

Thanks for the comments!

> 4)
> Shall we give an example LOG message in the end?

I feel the current insert_exists log in conflict section seems
sufficient as an example to show the real conflict log.

Other comments look good, and I will address.

Best Regards,
Hou zj

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

21 August 2024, 12:33:02

On Wednesday, August 21, 2024 1:31 PM Kuroda, Hayato/黒田 隼人 <kuroda.hayato@fujitsu.com> wrote:
> 
> Dear Hou,
> 
> Thanks for updating the patch! I think the patch is mostly good.
> Here are minor comments.

Thanks for the comments !

> 
> 02.
> ```
> +     <para>
> +      The <literal>key</literal> section in the second sentence of the
> ...
> ```
> 
> I preferred that section name is quoted.

I thought about this. But I feel the 'key' here is not a real string, so I chose not to
add quote for it.

> 
> 0002:
> 
> 03.
> ```
> -#include "replication/logicalrelation.h"
> ```
> 
> Just to confirm - this removal is not related with the feature but just the
> improvement, right?

The logicalrelation.h becomes unnecessary after adding worker_intenral.h, so I
think it's this patch's job to remove this.

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

21 August 2024, 13:35:21

On Wed, Aug 21, 2024 at 8:35 AM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> On Wednesday, August 21, 2024 9:33 AM Jonathan S. Katz <jkatz@postgresql.org> wrote:
> > On 8/6/24 4:15 AM, Zhijie Hou (Fujitsu) wrote:
> >
> > > Thanks for the idea! I thought about few styles based on the suggested
> > > format, what do you think about the following ?
> >
> > Thanks for proposing formats. Before commenting on the specifics, I do want to
> > ensure that we're thinking about the following for the log formats:
> >
> > 1. For the PostgreSQL logs, we'll want to ensure we do it in a way that's as
> > convenient as possible for people to parse the context from scripts.
>
> Yeah. And I personally think the current log format is OK for parsing purposes.
>
> >
> > 2. Semi-related, I still think the simplest way to surface this info to a user is
> > through a "pg_stat_..." view or similar catalog mechanism (I'm less opinionated
> > on the how outside of we should make it available via SQL).
>
> We have a patch(v19-0002) in this thread to collect conflict stats and display
> them in the view, and the patch is under review.
>

IIUC, Jonathan is asking to store the conflict information (the one we
display in LOGs). We can do that separately as that is useful.

> Storing it into a catalog needs more analysis as we may need to add addition
> logic to clean up old conflict data in that catalog table. I think we can
> consider it as a future improvement.
>

Agreed. The cleanup part needs more consideration.

> >
> > 3. We should ensure we're able to convey to the user these details about the
> > conflict:
> >
> > * What time it occurred on the local server (which we'd have in the logs)
> > * What kind of conflict it is
> > * What table the conflict occurred on
> > * What action caused the conflict
> > * How the conflict was resolved (ability to include source/origin info)
>
> I think all above are already covered in the current conflict log. Except that
> we have not support resolving the conflict, so we don't log the resolution.
>
> >
> >
> > I think outputting the remote/local tuple value may be a parameter we need to
> > think about (with the desired outcome of trying to avoid another parameter). I
> > have a concern about unintentionally leaking data (and I understand that
> > someone with access to the logs does have a broad ability to view data); I'm
> > less concerned about the size of the logs, as conflicts in a well-designed
> > system should be rare (though a conflict storm could fill up the logs, likely there
> > are other issues to content with at that point).
>
> We could use an option to control, but the tuple value is already output in some
> existing cases (e.g. partition check, table constraints check, view with check
> constraints, unique violation), and it would test the current user's
> privileges to decide whether to output the tuple or not. So, I think it's OK
> to display the tuple for conflicts.
>

The current information is displayed keeping in mind that users should
be able to use that to manually resolve conflicts if required. If we
think there is a leak of information (either from a security angle or
otherwise) like tuple data then we can re-consider. However, as we are
displaying tuple information in other places as pointed out by
Hou-San, we thought it is also okay to display in this case.

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

22 August 2024, 06:25:24

On Wed, Aug 21, 2024 at 3:04 PM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
>
> Attach the V20 patch set which addressed above, Shveta[1][2] and Kuroda-san's[3]
> comments.
>

Thank You for the patch. Few comments:

1)
+ The key section includes the key values of the local tuple that
violated a unique constraint insert_exists or update_exists conflicts.

 --I think something  is missing in this line. Maybe add a 'for' or
*in case of*:
 The key section includes the key values of the local tuple that
violated a unique constraint *in case of*/*for* insert_exists or
update_exists conflicts.

2)
+ The replica identity section includes the replica identity key
values that used to search for the existing local tuple to be updated
or deleted.

--that *were* used to

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Peter Smith

Date:

22 August 2024, 11:02:52

Hi Hou-san.

I was experimenting with some conflict logging and found that large
column values are truncated in the log DETAIL.

E.g. Below I have a table where I inserted a 3000 character text value
'bigbigbig..."

Then I caused a replication conflict.

test_sub=# delete fr2024-08-22 17:50:17.181 AEST [14901] LOG:  logical
replication apply worker for subscription "sub1" has started
2024-08-22 17:50:17.193 AEST [14901] ERROR:  conflict detected on
relation "public.t1": conflict=insert_exists
2024-08-22 17:50:17.193 AEST [14901] DETAIL:  Key already exists in
unique index "t1_pkey", modified in transaction 780.
Key (a)=(k3); existing local tuple (k3,
bigbigbigbigbigbigbigbigbigbigbigbigbigbigbigbigbigbigbigbigbigb...);
remote tuple (k3, this will clash).

~

Do you think the documentation for the 'column_value' parameter of the
conflict logging should say that the displayed value might be
truncated?

======
Kind Regards,
Peter Smith.
Fujitsu Australia

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

22 August 2024, 11:51:42

On Thu, Aug 22, 2024 at 1:33 PM Peter Smith <smithpb2250@gmail.com> wrote:
>
> Do you think the documentation for the 'column_value' parameter of the
> conflict logging should say that the displayed value might be
> truncated?
>

I updated the patch to mention this and pushed it.

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

26 August 2024, 12:52:01

On Thu, Aug 22, 2024 at 2:21 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Thu, Aug 22, 2024 at 1:33 PM Peter Smith <smithpb2250@gmail.com> wrote:
> >
> > Do you think the documentation for the 'column_value' parameter of the
> > conflict logging should say that the displayed value might be
> > truncated?
> >
>
> I updated the patch to mention this and pushed it.
>

Peter Smith mentioned to me off-list that the names of conflict types
'update_differ' and 'delete_differ' are not intuitive as compared to
all other conflict types like insert_exists, update_missing, etc. The
other alternative that comes to mind for those conflicts is to name
them as 'update_origin_differ'/''delete_origin_differ'.

The description in docs for 'update_differ' is as follows: Updating a
row that was previously modified by another origin. Note that this
conflict can only be detected when track_commit_timestamp is enabled
on the subscriber. Currently, the update is always applied regardless
of the origin of the local row.

Does anyone else have any thoughts on the naming of these conflicts?

--
With Regards,
Amit Kapila.

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

26 August 2024, 13:36:29

On Mon, Aug 26, 2024 at 3:22 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Thu, Aug 22, 2024 at 2:21 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Thu, Aug 22, 2024 at 1:33 PM Peter Smith <smithpb2250@gmail.com> wrote:
> > >
> > > Do you think the documentation for the 'column_value' parameter of the
> > > conflict logging should say that the displayed value might be
> > > truncated?
> > >
> >
> > I updated the patch to mention this and pushed it.
> >
>
> Peter Smith mentioned to me off-list that the names of conflict types
> 'update_differ' and 'delete_differ' are not intuitive as compared to
> all other conflict types like insert_exists, update_missing, etc. The
> other alternative that comes to mind for those conflicts is to name
> them as 'update_origin_differ'/''delete_origin_differ'.

+1 on  'update_origin_differ'/''delete_origin_differ'. Gives more clarity.

> The description in docs for 'update_differ' is as follows: Updating a
> row that was previously modified by another origin. Note that this
> conflict can only be detected when track_commit_timestamp is enabled
> on the subscriber. Currently, the update is always applied regardless
> of the origin of the local row.
>
> Does anyone else have any thoughts on the naming of these conflicts?
>
> --
> With Regards,
> Amit Kapila.

RE: Conflict detection and logging in logical replication

From

"Zhijie Hou (Fujitsu)"

Date:

26 August 2024, 15:14:19

On Monday, August 26, 2024 6:36 PM shveta malik <shveta.malik@gmail.com> wrote:
> 
> On Mon, Aug 26, 2024 at 3:22 PM Amit Kapila <amit.kapila16@gmail.com>
> wrote:
> >
> > On Thu, Aug 22, 2024 at 2:21 PM Amit Kapila <amit.kapila16@gmail.com>
> wrote:
> > >
> > > On Thu, Aug 22, 2024 at 1:33 PM Peter Smith <smithpb2250@gmail.com>
> wrote:
> > > >
> > > > Do you think the documentation for the 'column_value' parameter of
> > > > the conflict logging should say that the displayed value might be
> > > > truncated?
> > > >
> > >
> > > I updated the patch to mention this and pushed it.
> > >
> >
> > Peter Smith mentioned to me off-list that the names of conflict types
> > 'update_differ' and 'delete_differ' are not intuitive as compared to
> > all other conflict types like insert_exists, update_missing, etc. The
> > other alternative that comes to mind for those conflicts is to name
> > them as 'update_origin_differ'/''delete_origin_differ'.
> 
> +1 on  'update_origin_differ'/''delete_origin_differ'. Gives more clarity.

+1

> 
> > The description in docs for 'update_differ' is as follows: Updating a
> > row that was previously modified by another origin. Note that this
> > conflict can only be detected when track_commit_timestamp is enabled
> > on the subscriber. Currently, the update is always applied regardless
> > of the origin of the local row.
> >
> > Does anyone else have any thoughts on the naming of these conflicts?

Best Regards,
Hou zj

Re: Conflict detection and logging in logical replication

From

Peter Smith

Date:

27 August 2024, 02:07:10

On Mon, Aug 26, 2024 at 7:52 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
>
> On Thu, Aug 22, 2024 at 2:21 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Thu, Aug 22, 2024 at 1:33 PM Peter Smith <smithpb2250@gmail.com> wrote:
> > >
> > > Do you think the documentation for the 'column_value' parameter of the
> > > conflict logging should say that the displayed value might be
> > > truncated?
> > >
> >
> > I updated the patch to mention this and pushed it.
> >
>
> Peter Smith mentioned to me off-list that the names of conflict types
> 'update_differ' and 'delete_differ' are not intuitive as compared to
> all other conflict types like insert_exists, update_missing, etc. The
> other alternative that comes to mind for those conflicts is to name
> them as 'update_origin_differ'/''delete_origin_differ'.
>

For things to "differ" there must be more than one them. The plural of
origin is origins.

e.g. 'update_origins_differ'/''delete_origins_differ'.

OTOH, you could say "differs" instead of differ:

e.g. 'update_origin_differs'/''delete_origin_differs'.

======
Kind Regards,
Peter Smith.
Fujitsu Australia

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

28 August 2024, 06:30:17

On Tue, Aug 27, 2024 at 4:37 AM Peter Smith <smithpb2250@gmail.com> wrote:
>
> On Mon, Aug 26, 2024 at 7:52 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> >
> > On Thu, Aug 22, 2024 at 2:21 PM Amit Kapila <amit.kapila16@gmail.com> wrote:
> > >
> > > On Thu, Aug 22, 2024 at 1:33 PM Peter Smith <smithpb2250@gmail.com> wrote:
> > > >
> > > > Do you think the documentation for the 'column_value' parameter of the
> > > > conflict logging should say that the displayed value might be
> > > > truncated?
> > > >
> > >
> > > I updated the patch to mention this and pushed it.
> > >
> >
> > Peter Smith mentioned to me off-list that the names of conflict types
> > 'update_differ' and 'delete_differ' are not intuitive as compared to
> > all other conflict types like insert_exists, update_missing, etc. The
> > other alternative that comes to mind for those conflicts is to name
> > them as 'update_origin_differ'/''delete_origin_differ'.
> >
>
> For things to "differ" there must be more than one them. The plural of
> origin is origins.
>
> e.g. 'update_origins_differ'/''delete_origins_differ'.
>
> OTOH, you could say "differs" instead of differ:
>
> e.g. 'update_origin_differs'/''delete_origin_differs'.
>

+1 on 'update_origin_differs' instead of 'update_origins_differ' as
the former is somewhat similar to other conflict names 'insert_exists'
and 'update_exists'.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

shveta malik

Date:

28 August 2024, 08:53:01

On Wed, Aug 28, 2024 at 9:44 AM Zhijie Hou (Fujitsu)
<houzj.fnst@fujitsu.com> wrote:
>
> > > +1 on 'update_origin_differs' instead of 'update_origins_differ' as
> > > the former is somewhat similar to other conflict names 'insert_exists'
> > > and 'update_exists'.
> >
> > Since we reached a consensus on this, I am attaching a small patch to rename
> > as suggested.
>
> Sorry, I attached the wrong patch. Here is correct one.
>

LGTM.

thanks
Shveta

Re: Conflict detection and logging in logical replication

From

Peter Smith

Date:

28 August 2024, 09:54:27

On Wed, Aug 28, 2024 at 3:53 PM shveta malik <shveta.malik@gmail.com> wrote:
>
> On Wed, Aug 28, 2024 at 9:44 AM Zhijie Hou (Fujitsu)
> <houzj.fnst@fujitsu.com> wrote:
> >
> > > > +1 on 'update_origin_differs' instead of 'update_origins_differ' as
> > > > the former is somewhat similar to other conflict names 'insert_exists'
> > > > and 'update_exists'.
> > >
> > > Since we reached a consensus on this, I am attaching a small patch to rename
> > > as suggested.
> >
> > Sorry, I attached the wrong patch. Here is correct one.
> >
>
> LGTM.
>

LGTM.

======
Kind Regards,
Peter Smith.
Fujitsu Australia

Re: Conflict detection and logging in logical replication

From

Amit Kapila

Date:

28 August 2024, 12:37:04

On Wed, Aug 28, 2024 at 12:24 PM Peter Smith <smithpb2250@gmail.com> wrote:
>
> On Wed, Aug 28, 2024 at 3:53 PM shveta malik <shveta.malik@gmail.com> wrote:
> >
> > On Wed, Aug 28, 2024 at 9:44 AM Zhijie Hou (Fujitsu)
> > <houzj.fnst@fujitsu.com> wrote:
> > >
> > > > > +1 on 'update_origin_differs' instead of 'update_origins_differ' as
> > > > > the former is somewhat similar to other conflict names 'insert_exists'
> > > > > and 'update_exists'.
> > > >
> > > > Since we reached a consensus on this, I am attaching a small patch to rename
> > > > as suggested.
> > >
> > > Sorry, I attached the wrong patch. Here is correct one.
> > >
> >
> > LGTM.
> >
>
> LGTM.
>

I'll push this patch tomorrow unless there are any suggestions or comments.

--
With Regards,
Amit Kapila.