Fix timestamp of sent message for write context in logical decoding

When sending data for logical decoding using the streaming replication
protocol via a WAL sender, the timestamp of the sent write message is
allocated at the beginning of the message when preparing for the write,
and actually computed when the write message is ready to be sent.

The timestamp was getting computed after sending the message.  This
impacts anything using logical decoding, causing for example logical
replication to report mostly NULL for last_msg_send_time in
pg_stat_subscription.

This commit makes sure that the timestamp is computed before sending the
message.  This is wrong since 5a991ef, so backpatch down to 9.4.

Author: Jeff Janes
Discussion: https://postgr.es/m/CAMkU=1z=WMn8jt7iEdC5sYNaPgAgOASb_OW5JYv-vMdYaJSL-w@mail.gmail.com
Backpatch-through: 9.4

diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index b0ebe5039c46b3b284887cb9cdd6e2bff4ec5bb8..7f5671504f76df23d35a2be5a645e9cd0518a863 100644 (file)
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1180,9 +1180,6 @@ WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid,
 {
        TimestampTz now;
 
-       /* output previously gathered data in a CopyData packet */
-       pq_putmessage_noblock('d', ctx->out->data, ctx->out->len);
-
        /*
         * Fill the send timestamp last, so that it is taken as late as possible.
         * This is somewhat ugly, but the protocol is set as it's already used for
@@ -1194,6 +1191,9 @@ WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid,
        memcpy(&ctx->out->data[1 + sizeof(int64) + sizeof(int64)],
                   tmpbuf.data, sizeof(int64));
 
+       /* output previously gathered data in a CopyData packet */
+       pq_putmessage_noblock('d', ctx->out->data, ctx->out->len);
+
        CHECK_FOR_INTERRUPTS();
 
        /* Try to flush pending output to the client */