BUG #9849: walreceiver's DEBUG message reports wrong timestamp

The following bug has been logged on the website:

Bug reference:      9849
Logged by:          TAKATSUKA Haruka
Email address:      harukat@sraoss.co.jp
PostgreSQL version: 9.3.4
Operating system:   CentOS 6.2 (64bit / gcc 4.4.7)
Description:

We get the folloging message at the standby server.

 DEBUG:  sendtime 2014-04-04 11:26:02.425368+09 receipttime 2014-04-04
11:26:02.425368+09 replication apply delay 0 ms transfer latency 224043 ms

Though sendtime equals receipttime, transfer latency is large.
This receipttime may be wrong.

When I change the code as the following for as a trial,
messages that have same sendtime and receipttime are gone.

diff --git a/src/backend/replication/walreceiver.c
b/src/backend/replication/wal
index 43db108..af21b5d 100644
--- a/src/backend/replication/walreceiver.c
+++ b/src/backend/replication/walreceiver.c
@@ -1198,10 +1198,13 @@ ProcessWalSndrMessage(XLogRecPtr walEnd, TimestampTz
sen
        walrcv->lastMsgReceiptTime = lastMsgReceiptTime;
        SpinLockRelease(&walrcv->mutex);

-       if (log_min_messages <= DEBUG2)
+       if (log_min_messages <= DEBUG2) {
+               char* strSendTime = strdupa(timestamptz_to_str(sendTime));
+               char* strReceiptTime =
strdupa(timestamptz_to_str(lastMsgReceipt
+               int applyDelay = GetReplicationApplyDelay();
+               int transferLatency = GetReplicationTransferLatency();
+
                elog(DEBUG2, "sendtime %s receipttime %s replication apply
delay
-                        timestamptz_to_str(sendTime),
-                        timestamptz_to_str(lastMsgReceiptTime),
-                        GetReplicationApplyDelay(),
-                        GetReplicationTransferLatency());
+                        strSendTime, strReceiptTime, applyDelay,
transferLatenc
+       }
 }