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 44ce6240d7cb651c43df2b8fd1d308a3c0eff2c7..0d35e77fc17f8166684db2cd7e69028cb61e8668 100644 (file)
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1072,9 +1072,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
@@ -1087,6 +1084,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 */