Обсуждение: 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