Confusing with commit time usage in logical decoding

Started by Artur Zakirovalmost 10 years ago9 messages
#1Artur Zakirov
a.zakirov@postgrespro.ru

Hello,

I read this message
/messages/by-id/56D4197E.9050706@informatik.uni-kl.de

Is this a bug or a typo? In DecodeCommit() in decode.c instead of:

if (parsed->xinfo & XACT_XINFO_HAS_ORIGIN)
{
origin_lsn = parsed->origin_lsn;
commit_time = parsed->origin_timestamp;
}

should be:

if (parsed->xinfo & XACT_XINFO_HAS_ORIGIN)
{
origin_lsn = parsed->origin_lsn;
commit_time = parsed->origin_timestamp;
}
else
commit_time = parsed->xact_time;

--
Artur Zakirov
Postgres Professional: http://www.postgrespro.com
Russian Postgres Company

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

#2Artur Zakirov
a.zakirov@postgrespro.ru
In reply to: Artur Zakirov (#1)
1 attachment(s)
Re: Confusing with commit time usage in logical decoding

Hello, Andres

You have introduced a large replication progress tracking infrastructure
last year. And there is a problem described at the link in the quote below.

Attached patch fix this issue. Is this patch correct? I will be grateful
if it is and if it will be committed.

Thanks.

On 29.02.2016 14:18, Artur Zakirov wrote:

Hello,

I read this message
/messages/by-id/56D4197E.9050706@informatik.uni-kl.de

Is this a bug or a typo? In DecodeCommit() in decode.c instead of:

if (parsed->xinfo & XACT_XINFO_HAS_ORIGIN)
{
origin_lsn = parsed->origin_lsn;
commit_time = parsed->origin_timestamp;
}

should be:

if (parsed->xinfo & XACT_XINFO_HAS_ORIGIN)
{
origin_lsn = parsed->origin_lsn;
commit_time = parsed->origin_timestamp;
}
else
commit_time = parsed->xact_time;

--
Artur Zakirov
Postgres Professional: http://www.postgrespro.com
Russian Postgres Company

Attachments:

logical-decoding.patchtext/x-patch; name=logical-decoding.patchDownload
*** a/src/backend/replication/logical/decode.c
--- b/src/backend/replication/logical/decode.c
***************
*** 458,463 **** DecodeCommit(LogicalDecodingContext *ctx, XLogRecordBuffer *buf,
--- 458,465 ----
  		origin_lsn = parsed->origin_lsn;
  		commit_time = parsed->origin_timestamp;
  	}
+ 	else
+ 		commit_time = parsed->xact_time;
  
  	/*
  	 * Process invalidation messages, even if we're not interested in the
#3Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Artur Zakirov (#2)
Re: Confusing with commit time usage in logical decoding

Artur Zakirov wrote:

Hello, Andres

You have introduced a large replication progress tracking infrastructure
last year. And there is a problem described at the link in the quote below.

Attached patch fix this issue. Is this patch correct? I will be grateful if
it is and if it will be committed.

AFAICS this is clearly a bug introduced in 5aa235042:

    /* replay actions of all transaction + subtransactions in order */
    ReorderBufferCommit(ctx->reorder, xid, buf->origptr, buf->endptr,
-                       parsed->xact_time);
+                       commit_time, origin_id, origin_lsn);
 }

--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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

#4Petr Jelinek
petr@2ndquadrant.com
In reply to: Alvaro Herrera (#3)
Re: Confusing with commit time usage in logical decoding

On 01/03/16 17:57, Alvaro Herrera wrote:

Artur Zakirov wrote:

Hello, Andres

You have introduced a large replication progress tracking infrastructure
last year. And there is a problem described at the link in the quote below.

Attached patch fix this issue. Is this patch correct? I will be grateful if
it is and if it will be committed.

AFAICS this is clearly a bug introduced in 5aa235042:

/* replay actions of all transaction + subtransactions in order */
ReorderBufferCommit(ctx->reorder, xid, buf->origptr, buf->endptr,
-                       parsed->xact_time);
+                       commit_time, origin_id, origin_lsn);
}

Well yeah but the commit_time is set few lines above as Artur pointed
out, I think the proposed fix is correct one.

--
Petr Jelinek http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

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

#5Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Petr Jelinek (#4)
Re: Confusing with commit time usage in logical decoding

Petr Jelinek wrote:

On 01/03/16 17:57, Alvaro Herrera wrote:

Artur Zakirov wrote:

Hello, Andres

You have introduced a large replication progress tracking infrastructure
last year. And there is a problem described at the link in the quote below.

Attached patch fix this issue. Is this patch correct? I will be grateful if
it is and if it will be committed.

AFAICS this is clearly a bug introduced in 5aa235042:

/* replay actions of all transaction + subtransactions in order */
ReorderBufferCommit(ctx->reorder, xid, buf->origptr, buf->endptr,
-                       parsed->xact_time);
+                       commit_time, origin_id, origin_lsn);
}

Well yeah but the commit_time is set few lines above as Artur pointed out, I
think the proposed fix is correct one.

Err, yes, that's exactly what I am saying. Sorry for being unclear.

--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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

#6Andres Freund
andres@anarazel.de
In reply to: Petr Jelinek (#4)
Re: Confusing with commit time usage in logical decoding

Hi,

On 2016-03-01 18:09:28 +0100, Petr Jelinek wrote:

On 01/03/16 17:57, Alvaro Herrera wrote:

Artur Zakirov wrote:

Hello, Andres

You have introduced a large replication progress tracking infrastructure
last year. And there is a problem described at the link in the quote below.

Attached patch fix this issue. Is this patch correct? I will be grateful if
it is and if it will be committed.

AFAICS this is clearly a bug introduced in 5aa235042:

/* replay actions of all transaction + subtransactions in order */
ReorderBufferCommit(ctx->reorder, xid, buf->origptr, buf->endptr,
-                       parsed->xact_time);
+                       commit_time, origin_id, origin_lsn);
}

Well yeah but the commit_time is set few lines above as Artur pointed out, I
think the proposed fix is correct one.

I'd rather just initialize commit_time to parsed->xact_time.

This indeed is clearly a bug. I do wonder if anybody has a good idea
about how to add regression tests for this? It's rather annoying that
we have to suppress timestamps in the test_decoding tests, because
they're obviously not reproducible...

Andres

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

#7Alvaro Herrera
alvherre@2ndquadrant.com
In reply to: Andres Freund (#6)
Re: Confusing with commit time usage in logical decoding

Andres Freund wrote:

I'd rather just initialize commit_time to parsed->xact_time.

That also works.

Probably also change its declaration to actually be TimestampTz ...

This indeed is clearly a bug. I do wonder if anybody has a good idea
about how to add regression tests for this? It's rather annoying that
we have to suppress timestamps in the test_decoding tests, because
they're obviously not reproducible...

Maybe commit two transactions with a 1s sleep in between, and verify
that the difference between the two timestamps is >= 1s and <= now()?
(I don't know the test_decoding test suite)

--
�lvaro Herrera http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

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

#8Petr Jelinek
petr@2ndquadrant.com
In reply to: Andres Freund (#6)
Re: Confusing with commit time usage in logical decoding

On 01/03/16 18:18, Andres Freund wrote:

Hi,

On 2016-03-01 18:09:28 +0100, Petr Jelinek wrote:

On 01/03/16 17:57, Alvaro Herrera wrote:

Artur Zakirov wrote:

Hello, Andres

You have introduced a large replication progress tracking infrastructure
last year. And there is a problem described at the link in the quote below.

Attached patch fix this issue. Is this patch correct? I will be grateful if
it is and if it will be committed.

AFAICS this is clearly a bug introduced in 5aa235042:

/* replay actions of all transaction + subtransactions in order */
ReorderBufferCommit(ctx->reorder, xid, buf->origptr, buf->endptr,
-                       parsed->xact_time);
+                       commit_time, origin_id, origin_lsn);
}

Well yeah but the commit_time is set few lines above as Artur pointed out, I
think the proposed fix is correct one.

I'd rather just initialize commit_time to parsed->xact_time.

This indeed is clearly a bug. I do wonder if anybody has a good idea
about how to add regression tests for this? It's rather annoying that
we have to suppress timestamps in the test_decoding tests, because
they're obviously not reproducible...

The test for commit timestamps checks that the timestamps are within
reasonable time frame (for example, bigger than value of a timestamp
column in the table since that's assigned before commit obviously) ,
it's not perfect but similar approach should catch issues like this one.

--
Petr Jelinek http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

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

#9Andres Freund
andres@anarazel.de
In reply to: Petr Jelinek (#8)
Re: Confusing with commit time usage in logical decoding

On 2016-03-01 18:31:42 +0100, Petr Jelinek wrote:

On 01/03/16 18:18, Andres Freund wrote:

I'd rather just initialize commit_time to parsed->xact_time.

This indeed is clearly a bug. I do wonder if anybody has a good idea
about how to add regression tests for this? It's rather annoying that
we have to suppress timestamps in the test_decoding tests, because
they're obviously not reproducible...

The test for commit timestamps checks that the timestamps are within
reasonable time frame (for example, bigger than value of a timestamp column
in the table since that's assigned before commit obviously) , it's not
perfect but similar approach should catch issues like this one.

Fixed, including such a test. Thanks for the report; and for the idea of
the fix!

Andres

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