Thread: Question about WalSndWriteData

Hi hackes,

I confused by the following code in WalSndWriteData:

     /* 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 is set as it's already 
used for
      * several releases by streaming physical replication.
      */
     resetStringInfo(&tmpbuf);
     now = GetCurrentTimestamp();
     pq_sendint64(&tmpbuf, now);
     memcpy(&ctx->out->data[1 + sizeof(int64) + sizeof(int64)],
            tmpbuf.data, sizeof(int64));


pq_putmessage_noblock copies data from ctx->out buffer to libpq buffers.
After it we write timestamp to ctx->out buffer.
And comments says that we should do it "as late as possible".
But this timestamp is not included in the copy data packet which is 
already copied to libpq connection buffer.
And next WalSndPrepareWrite call will reset ctx->out buffer.

So I wonder what is the reason of writing timestamp in ctx->out buffer 
after processing it by pq_putmessage_noblock?

-- 
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

On 3/16/18 12:08, Konstantin Knizhnik wrote:
> pq_putmessage_noblock copies data from ctx->out buffer to libpq buffers.
> After it we write timestamp to ctx->out buffer.
> And comments says that we should do it "as late as possible".
> But this timestamp is not included in the copy data packet which is 
> already copied to libpq connection buffer.

There is a pq_flush_if_writable() right after this that will write out
the rest of ctx->out.

-- 
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On 21.03.2018 04:50, Peter Eisentraut wrote:
> On 3/16/18 12:08, Konstantin Knizhnik wrote:
>> pq_putmessage_noblock copies data from ctx->out buffer to libpq buffers.
>> After it we write timestamp to ctx->out buffer.
>> And comments says that we should do it "as late as possible".
>> But this timestamp is not included in the copy data packet which is
>> already copied to libpq connection buffer.
> There is a pq_flush_if_writable() right after this that will write out
> the rest of ctx->out.
>
Sorry, But PQ_flush_if_writable calls socket_flush_if_writable (or 
mq_flush_if_writable).
This function flushes pqlib connection buffer, i.e. PqSendBuffer.
This buffer has no relation to ctx->out_buffer, where timestamp is written.

The obvious fix is to move assignment of timestamp prior to 
pq_putmessage_noblock:


WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, 
TransactionId xid,
                 bool last_write)
{
     TimestampTz    now;

     /*
      * Fill the send timestamp last, so that it is taken as late as 
possible.
      * This is somewhat ugly, but the protocol is set as it's already 
used for
      * several releases by streaming physical replication.
      */
     resetStringInfo(&tmpbuf);
     now = GetCurrentTimestamp();
     pq_sendint64(&tmpbuf, now);
     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);



-- 
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

On 21.03.2018 10:08, Konstantin Knizhnik wrote:
>
>
> On 21.03.2018 04:50, Peter Eisentraut wrote:
>> On 3/16/18 12:08, Konstantin Knizhnik wrote:
>>> pq_putmessage_noblock copies data from ctx->out buffer to libpq 
>>> buffers.
>>> After it we write timestamp to ctx->out buffer.
>>> And comments says that we should do it "as late as possible".
>>> But this timestamp is not included in the copy data packet which is
>>> already copied to libpq connection buffer.
>> There is a pq_flush_if_writable() right after this that will write out
>> the rest of ctx->out.
>>
> Sorry, But PQ_flush_if_writable calls socket_flush_if_writable (or 
> mq_flush_if_writable).
> This function flushes pqlib connection buffer, i.e. PqSendBuffer.
> This buffer has no relation to ctx->out_buffer, where timestamp is 
> written.
>
> The obvious fix is to move assignment of timestamp prior to 
> pq_putmessage_noblock:
>
>
> WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, 
> TransactionId xid,
>                 bool last_write)
> {
>     TimestampTz    now;
>
>     /*
>      * Fill the send timestamp last, so that it is taken as late as 
> possible.
>      * This is somewhat ugly, but the protocol is set as it's already 
> used for
>      * several releases by streaming physical replication.
>      */
>     resetStringInfo(&tmpbuf);
>     now = GetCurrentTimestamp();
>     pq_sendint64(&tmpbuf, now);
>     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);
>
>
>

Sorry, I have not received confirmation whether it is a bug or not and 
is it going to be fixed.

-- 
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

Hello,

At Thu, 29 Mar 2018 20:11:03 +0300, Konstantin Knizhnik <k.knizhnik@postgrespro.ru> wrote in
<04171363-a07d-62b7-4362-32de5414941c@postgrespro.ru>
> 
> 
> On 21.03.2018 10:08, Konstantin Knizhnik wrote:
> >
> >
> > On 21.03.2018 04:50, Peter Eisentraut wrote:
> >> On 3/16/18 12:08, Konstantin Knizhnik wrote:
> >>> pq_putmessage_noblock copies data from ctx->out buffer to libpq
> >>> buffers.
> >>> After it we write timestamp to ctx->out buffer.
> >>> And comments says that we should do it "as late as possible".
> >>> But this timestamp is not included in the copy data packet which is
> >>> already copied to libpq connection buffer.
> >> There is a pq_flush_if_writable() right after this that will write out
> >> the rest of ctx->out.
> >>
> > Sorry, But PQ_flush_if_writable calls socket_flush_if_writable (or
> > mq_flush_if_writable).
> > This function flushes pqlib connection buffer, i.e. PqSendBuffer.
> > This buffer has no relation to ctx->out_buffer, where timestamp is
> > written.
> >
> > The obvious fix is to move assignment of timestamp prior to
> > pq_putmessage_noblock:

Yeah. The content of ctx->out is already copied into the buffer
inside libpq. So rewriting ctx->out doesn't have an effeict after
putmessage. Actually LogicalRepApplyLoop always receives packets
with send_time = 0! I overlooked that while discussing there..

It is also set by keep-alive message so we don't observe
pg_stat_subscription.last_msg_send_time to be null so often but
we can surely see it. (it is artificially caused by inserting a
wait just after UpdateWorkerStats call for 'w' message in
LogicalRepApplyLoop)

 select * from pg_stat_subscription ;
-[ RECORD 1 ]---------+------------------------------
subid                 | 16390
subname               | sub1
pid                   | 17191
relid                 | 
received_lsn          | 0/1C0FDAE0
last_msg_send_time    | 
last_msg_receipt_time | 2018-03-30 14:18:55.270096+09
latest_end_lsn        | 0/1C0FDA70
latest_end_time       | 2018-03-30 14:18:48.268534+09

> Sorry, I have not received confirmation whether it is a bug or not and
> is it going to be fixed.

So, my diagnosis is that this is apparently a bug, which should
be fixed as Konstantin is proposing. And it should be back-patched?


regards,

-- 
Kyotaro Horiguchi
NTT Open Source Software Center