Buffer transaction statements to disk to prevent replay deadlock #505

arajkumar · 2023-10-20T02:29:32Z

This commit buffers transactions being replayed into a separate file until
the entire transaction body is received. It addresses potential deadlocks
that can occur when the BEGIN message arrives before the creation of the
transaction metadata file by the transform process.

Signed-off-by: Arunprasad Rajkumar ar.arunprasad@gmail.com

arajkumar · 2023-10-22T13:54:05Z

@dimitri The latest changes uses spills to disk approach to buffer transactions in replay mode.

dimitri · 2023-10-23T13:51:49Z

Could we store the current transaction to a file named ${xid}.sql ; and maybe add a static filename as you did but this time as a symlink to the current transaction file? I believe that would make things more obvious when debugging live situations.

arajkumar · 2023-10-25T10:42:07Z

@dimitri I've added a symlink to the latest transaction buffer as suggested by you. Additionally KEEPALIVE, SWITCHWAL and ENDPOS messages which comes out of transaction will be replayed without buffering those.

dimitri

Thanks for your work, I believe we're close to being able to merge this improvement! Please see my review and consider the changes I'm asking for.

src/bin/pgcopydb/copydb.c

src/bin/pgcopydb/ld_replay.c

dimitri · 2023-10-25T11:12:40Z

src/bin/pgcopydb/ld_replay.c

+		/* If there is already a replay buffer open, it indicates a partial
+		 * transaction. Close it and start a new one.
+		 */
+		if (replayCtx->txnReplayBuffer != NULL)
+		{
+			fclose(replayCtx->txnReplayBuffer);
+		}


I'm not sure I follow how this is not an ERROR (or a WARN) situation? When does that happen in a normal execution?

~~The idea is to use similar fix for prefetch mode as well, during the resume, we might encounter partially written txns. But that doesn't apply for replay. I would rather add an error message here.~~

This happens while switching from prefetch to replay mode, the transform process invokes stream_transform_resume which leads to playback of partial file created by prefetch and it might have partial transaction.

In one of my test, 00000004000001590000007E.sql was partially written by the prefetch. While switching to replay, transform applies the partial file leading to the unexpected state!

2023-10-25 13:42:04 600127 INFO follow.c:355 Restarting logical decoding follower in replay mode
2023-10-25 13:42:04 600135 NOTICE follow.c:814 Starting the prefetch sub-process
2023-10-25 13:42:04 600136 NOTICE follow.c:814 Starting the transform sub-process
2023-10-25 13:42:04 600136 SQL pgsql.c:508 Connecting to [source] "postgres://tsdbadmin@tsdb-22e8519b-internal-90d0.a.timescaledb.io:26479/defaultdb?sslmode=require&keepalives=1&keepalives_idle=10&keepalives_interval=10&keepalives_count=60"
2023-10-25 13:42:04 600137 NOTICE follow.c:814 Starting the catchup sub-process
2023-10-25 13:42:04 600135 INFO ld_stream.c:1987 Resuming streaming from latest file "/home/ubuntu/.local/share/pgcopydb/00000004000001590000007E.json"
2023-10-25 13:42:04 600136 NOTICE ld_transform.c:234 Transforming from 159/7EE2F578 in "/home/ubuntu/.local/share/pgcopydb/00000004000001590000007E.sql"
2023-10-25 13:42:04 600136 NOTICE ld_transform.c:794 Transforming JSON file "/home/ubuntu/.local/share/pgcopydb/00000004000001590000007E.json" into SQL file "/home/ubuntu/.local/share/pgcopydb/00000004000001590000007E.sql"
...
2023-10-25 13:42:04 600137 INFO ld_apply.c:254 Replaying changes from LSN 159/7EE24298
2023-10-25 13:42:04 600137 ERROR ld_replay.c:363 BUG: Received COMMIT; -- {"xid":7789156,"lsn":"159/7E001210","timestamp":"2023-10-25 13:41:56.473524+0000"} when transaction is not in buffering mode

00000004000001590000007E.sql

COMMIT; -- {"xid":7789156,"lsn":"159/7E001210","timestamp":"2023-10-25 13:41:56.473524+0000"}
BEGIN; -- {"xid":7789155,"lsn":"159/7DFD6498","timestamp":"2023-10-25 13:41:56.511105+0000","commit_lsn":"159/7E008390"}
PREPARE 40ba08bf AS INSERT INTO public.readings
...
...

@dimitri, Is there a better way to deal with this?

Even in prefetch mode we would only encounter a single partial transaction I believe, the last one we received. Cases where we would deal with a partial transaction and then another transaction certainly indicate a bug?

Even in prefetch mode we would only encounter a single partial transaction I believe, the last one we received.

This is what is happening. We have to ignore the partial transactions (i.e. either a COMMIT without a BEGIN or BEGIN without COMMIT).

I addressed all the review comments except this.

I think I still have some with the code (the comments are good at explaining the situation, thanks). The trouble is that we don't protect against applying this approach even in the middle of our operations, when it looks like it's only needed before we reach our own “consistent point”, never after that. Can we make sure that as soon as we start replaying transactions, then we raise the situation from a DEBUG information to an actual ERROR? (well assuming my analysis is correct here).

src/bin/pgcopydb/ld_replay.c

dimitri

Getting there!

src/bin/pgcopydb/ld_replay.c

This commit buffers transactions being replayed into a separate file until the entire transaction body is received. It addresses potential deadlocks that can occur when the BEGIN message arrives before the creation of the transaction metadata file by the transform process. Signed-off-by: Arunprasad Rajkumar <ar.arunprasad@gmail.com>

dimitri · 2023-10-26T08:41:10Z

src/bin/pgcopydb/ld_replay.c

+			 * After switching to the replay mode, logical decoding will resume
+			 * from consistent point which again starts with a valid transcation
+			 * block.


Do we have the LSN value for that consistent point available in the context here? If yes, I believe we should be using it to make sure we are skipping transactions as intended. If no, then we should add to the comment why not, so that another PR later can go and fix the situation if we feel like it should be fixed.

@dimitri This is a great point ! I think the current ignore logic implemented in this PR might cause inconsistency where it might ignore the partial transaction, but applies the next transaction because it has valid BEGIN/COMMIT block.

I need to have a another deep look now.

@dimitri I was wrong in my previous comment.

While switching to replay mode, follow ensures that the pending LSNs in transform queue has been processed and applied to the target. This ensures everything except the last the partial transaction has been successfully committed into the target. After switching to replay mode, stream_transform_resume again streams the last partial file(which is already applied by the previous step) to the replay process which leads to this scenario. I think streaming last partial .sql from stream_transform_resume is redundant and shall be removed and this shouldn't cause any issue. WDYT?

I'm wondering are these PRs #348, #277 trying to do the same in different ways?

I no longer see partial txn when I remove part of the code from stream_transform_resume which streams partial sql., I didn't see any data loss either.

IIRC the transform parts need to parse/load the latest file to build up the context in case we stopped in the middle of a transaction (we then need to have the start of the transaction in-memory); but I agree we don't need to send that to the replay process, which is only going to skip again.

That said the skip logic is sound and I wonder why in your PR we can't benefit from it?

dimitri · 2023-10-26T08:43:25Z

src/bin/pgcopydb/ld_replay.c

+			log_debug("Received %s when transaction is already "
+					  "in buffering mode, ignoring.", line);


Please rewrite the message so that it ends with ": %s", line. This makes it easier to process the logs later.

dimitri · 2023-10-26T08:43:59Z

src/bin/pgcopydb/ld_replay.c

+			log_debug("Received %s when transaction is not "
+					  "in buffering mode, ignoring.", line);


Please rewrite the message so that it ends with ": %s", line. This makes it easier to process the logs later.

dimitri · 2023-10-26T08:44:23Z

src/bin/pgcopydb/ld_replay.c

+			log_debug("Received %s when transaction is not "
+					  "in buffering mode", line);


Please rewrite the message so that it ends with ": %s", line. This makes it easier to process the logs later.

arajkumar · 2023-11-01T07:33:01Z

#525 fixes by eliminating the need of txn metadata file.

arajkumar mentioned this pull request Oct 20, 2023

pgcopydb hangs on while doing pgcopydb clone --follow #493

Closed

arajkumar force-pushed the buffer-replay-statements branch from eb5f0c6 to f3c8bdd Compare October 22, 2023 13:52

arajkumar force-pushed the buffer-replay-statements branch 2 times, most recently from a369b17 to e609c67 Compare October 22, 2023 13:56

arajkumar force-pushed the buffer-replay-statements branch from e609c67 to c17fd8e Compare October 25, 2023 10:33

arajkumar changed the title ~~Buffer replay statements to avoid deadlock~~ Buffer transaction statements to disk to prevent replay deadlock Oct 25, 2023

arajkumar marked this pull request as ready for review October 25, 2023 10:35

arajkumar force-pushed the buffer-replay-statements branch from c17fd8e to 985144c Compare October 25, 2023 10:39

dimitri requested changes Oct 25, 2023

View reviewed changes

arajkumar force-pushed the buffer-replay-statements branch from 985144c to d35ca1a Compare October 25, 2023 14:19

dimitri requested changes Oct 25, 2023

View reviewed changes

arajkumar force-pushed the buffer-replay-statements branch from d35ca1a to 26e70a5 Compare October 25, 2023 18:59

arajkumar force-pushed the buffer-replay-statements branch from 26e70a5 to 21463c7 Compare October 25, 2023 19:06

arajkumar requested a review from dimitri October 26, 2023 05:35

dimitri requested changes Oct 26, 2023

View reviewed changes

dimitri added this to the v0.14 milestone Oct 26, 2023

dimitri mentioned this pull request Oct 26, 2023

Fix memory allocation issue in transform #511

Open

arajkumar closed this Nov 1, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Buffer transaction statements to disk to prevent replay deadlock #505

Buffer transaction statements to disk to prevent replay deadlock #505

arajkumar commented Oct 20, 2023 •

edited

Loading

arajkumar commented Oct 22, 2023

dimitri commented Oct 23, 2023

arajkumar commented Oct 25, 2023

dimitri left a comment

dimitri Oct 25, 2023

arajkumar Oct 25, 2023 •

edited

Loading

dimitri Oct 25, 2023

arajkumar Oct 25, 2023

arajkumar Oct 25, 2023

dimitri Oct 26, 2023

dimitri left a comment

dimitri Oct 26, 2023

arajkumar Oct 26, 2023

arajkumar Oct 27, 2023

arajkumar Oct 28, 2023 •

edited

Loading

dimitri Oct 30, 2023

dimitri Oct 26, 2023

dimitri Oct 26, 2023

dimitri Oct 26, 2023

arajkumar commented Nov 1, 2023

		log_debug("Received %s when transaction is already "
		"in buffering mode, ignoring.", line);

		log_debug("Received %s when transaction is not "
		"in buffering mode", line);

Buffer transaction statements to disk to prevent replay deadlock #505

Buffer transaction statements to disk to prevent replay deadlock #505

Conversation

arajkumar commented Oct 20, 2023 • edited Loading

arajkumar commented Oct 22, 2023

dimitri commented Oct 23, 2023

arajkumar commented Oct 25, 2023

dimitri left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arajkumar Oct 25, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dimitri left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arajkumar Oct 28, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

arajkumar commented Nov 1, 2023

arajkumar commented Oct 20, 2023 •

edited

Loading

arajkumar Oct 25, 2023 •

edited

Loading

arajkumar Oct 28, 2023 •

edited

Loading