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

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

From
harukat@sraoss.co.jp
Date:
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
+       }
 }

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

From
Tom Lane
Date:
harukat@sraoss.co.jp writes:
> 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.

Yeah, somebody forgot that timestamptz_to_str returns a static buffer.

strdupa is not a portable solution though.

            regards, tom lane