Thread

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

   TAKATSUKA Haruka <harukat@sraoss.co.jp> — 2014-04-04T10:22:16Z

   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
   +       }
    }
   
   
   
   

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

   Tom Lane <tgl@sss.pgh.pa.us> — 2014-04-04T14:49:57Z

   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