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 685cb40d089685f7a761b4befa3b9d96b8a6e4ab..84b08e945f88477eba36e11d8814aaec988e4b5c 100644 (file)
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1074,9 +1074,6 @@ WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid,
        TimestampTz     now;
        int64 now_int;
 
-       /* 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's set as it's already used for
@@ -1089,6 +1086,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 */