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(at)sraoss(dot)co(dot)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
+ }
}