Thread: [Todo item] Add entry creation timestamp column topg_stat_replication

Hello hackers,
 
I have worked on following todo list item.
 
  - Add entry creation timestamp column to pg_stat_replication
    http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
 
This item looks like simple because necessary data was already exist.
So, I wrote a prototype patch.
 
test example>
postgres=# select pid, reply_time from pg_stat_replication;
-[ RECORD 1 ]-----------------------------
pid        | 4817
reply_time | 2018-07-31 12:00:53.911198+09
-[ RECORD 2 ]-----------------------------
pid        | 4819
reply_time | 2018-07-31 12:00:53.911154+09
 
 
Several candidates exist for the field name.
    - reply_timestamp
    - info_gen_timestamp
    - stats_reset
    - last_msg_send_time
 
Feedback and suggestion will be very welcome.
Thanks!
 
Best regards,
Myungkyu, Lim

I changed field name from 'reply_time' to 'last_msg_send_time'.
Because 'last_msg_send_time' is used in pg_stat_wal_receiver/pg_stat_subsctiption view.
I think that field has the same meaning.

test example>
postgres=# select pid, last_msg_send_time from pg_stat_replication;
-[ RECORD 1 ]------+------------------------------
pid                | 12015
last_msg_send_time | 2018-08-02 18:02:49.233049+09
-[ RECORD 2 ]------+------------------------------
pid                | 12084
last_msg_send_time | 2018-08-02 18:02:48.583256+09

I Attached new patch file : 0001-Implement-following-TODO-list-item-v2.patch

Feedback and suggestion will be very welcome.
Thanks!

Best regards,
Myungkyu, Lim
 
--------- Original Message ---------
Date   : 2018-07-31 17:56 (GMT+9)
Title  : [Todo item] Add entry creation timestamp column to pg_stat_replication
 
Hello hackers,
 
I have worked on following todo list item.
 
  - Add entry creation timestamp column to pg_stat_replication
    http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
 
This item looks like simple because necessary data was already exist.
So, I wrote a prototype patch.
 
test example>
postgres=# select pid, reply_time from pg_stat_replication;
-[ RECORD 1 ]-----------------------------
pid        | 4817
reply_time | 2018-07-31 12:00:53.911198+09
-[ RECORD 2 ]-----------------------------
pid        | 4819
reply_time | 2018-07-31 12:00:53.911154+09
 
 
Several candidates exist for the field name.
    - reply_timestamp
    - info_gen_timestamp
    - stats_reset
    - last_msg_send_time
 
Feedback and suggestion will be very welcome.
Thanks!
 
Best regards,
Myungkyu, Lim

MyungKyu LIM wrote:
> I have worked on following todo list item.
>  
>   - Add entry creation timestamp column to pg_stat_replication
>     http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
>  
> This item looks like simple because necessary data was already exist.
> So, I wrote a prototype patch.

Thank you!

You should add this to the next commitfest:
https://commitfest.postgresql.org/20/

Please make sure to read the Developer FAQ if you haven't already done it:
https://wiki.postgresql.org/wiki/Developer_FAQ

Yours,
Laurenz Albe

Thanks for your feedback!

Include documentation for new column.
Attached new patch file
  : 0001-Implement-following-TODO-list-item-v3.patch

Best regards,
Myungkyu, Lim
 
--------- Original Message ---------
Sender : Laurenz Albe <laurenz.albe@cybertec.at>
Date   : 2018-10-25 15:14 (GMT+9)
Title  : Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
 
MyungKyu LIM wrote:
> I have worked on following todo list item.
>  
>   - Add entry creation timestamp column to pg_stat_replication
>     http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
>  
> This item looks like simple because necessary data was already exist.
> So, I wrote a prototype patch.
 
Thank you!
 
You should add this to the next commitfest:
https://commitfest.postgresql.org/20/
 
Please make sure to read the Developer FAQ if you haven't already done it:
https://wiki.postgresql.org/wiki/Developer_FAQ
 
Yours,
Laurenz Albe
 
 
 

Thanks for your feedback and info!

I registered patch in commit fest.
https://commitfest.postgresql.org/20/1841/

For the record, replied on original thread.

Best regards,
Myungkyu, Lim

-----Original Message-----
From: Michael Paquier [mailto:michael@paquier.xyz] 
Sent: Thursday, October 25, 2018 8:50 PM
To: Laurenz Albe
Cc: myungkyu.lim@samsung.com; pgsql-hackers@postgresql.org
Subject: Re: pg_stat_replication vs StandbyReplyMessage

On Thu, Oct 25, 2018 at 08:13:53AM +0200, Laurenz Albe wrote:
> MyungKyu LIM wrote:
>> I saw this topic in todo list,
>> 
>> so I implemented simple patch.
>> 
>> https://www.postgresql.org/message-id/flat/1657809367.407321.15330274
>> 17725.JavaMail.jboss%40ep2ml404
> 
> For the archives' sake, please always reply on the original thread.

And if you could add some documentation into the patch, and register it to the commit fest if you would like to get it
reviewed,that would be nice.  Here are some general guidelines on the matter:
 
https://wiki.postgresql.org/wiki/Submitting_a_Patch
--
Michael

Hi.
Thanks for your feedback.

> Can you explain the purpose of this feature more because now we have columns to report replication delay times like
write_lag,flush_lag and replay_lag that can use for similar purpose . 

I think, time elapsed stats are very useful on DML query active system,
but not present that stats on idle system - not query, or only select.

sent_lsn           | 0/5476C88
write_lsn          | 0/5476C88
flush_lsn          | 0/5476C88
replay_lsn         | 0/5476C88
write_lag          | 00:00:00.000055
flush_lag          | 00:00:00.000855
replay_lag         | 00:00:00.000914
sync_priority      | 0
sync_state         | async
last_msg_send_time | 2018-11-15 14:04:39.65889+09

state              | streaming
sent_lsn           | 0/5476CC0
write_lsn          | 0/5476CC0
flush_lsn          | 0/5476CC0
replay_lsn         | 0/5476CC0
write_lag          |
flush_lag          |
replay_lag         |
sync_priority      | 0
sync_state         | async
last_msg_send_time | 2018-11-15 14:05:02.935457+09

state              | streaming
sent_lsn           | 0/5476CC0
write_lsn          | 0/5476CC0
flush_lsn          | 0/5476CC0
replay_lsn         | 0/5476CC0
write_lag          |
flush_lag          |
replay_lag         |
sync_priority      | 0
sync_state         | async
last_msg_send_time | 2018-11-15 14:06:23.128947+09

This timestamp column is useful when react interval check and debugging on idle system.

Best regards,
Myungkyu, Lim

On Thu, Aug 2, 2018 at 6:34 PM MyungKyu LIM <myungkyu.lim@samsung.com> wrote:
>
> I changed field name from 'reply_time' to 'last_msg_send_time'.
> Because 'last_msg_send_time' is used in pg_stat_wal_receiver/pg_stat_subsctiption view.
> I think that field has the same meaning.

I got confused by the field name. If we have 'last_msg_send_time'
field in pg_stat_replciation which has information of wal senders
users would think it as a time when the wal sender sent a message last
time. However values of the fields actually shows a time when the wal
receiver sent a reply message last time. So perhaps
'last_reply_send_time' would be more clear.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

Hi.

>> I changed field name from 'reply_time' to 'last_msg_send_time'.
>> Because 'last_msg_send_time' is used in pg_stat_wal_receiver/pg_stat_subsctiption view.
>> I think that field has the same meaning.
>
>I got confused by the field name. If we have 'last_msg_send_time'
>field in pg_stat_replciation which has information of wal senders
>users would think it as a time when the wal sender sent a message last
>time. However values of the fields actually shows a time when the wal
>receiver sent a reply message last time. So perhaps
>'last_reply_send_time' would be more clear.

Good point. 'last_reply_send_time' is better.
How about just 'reply_time'?

Best regards,
Myungkyu, Lim

On Thu, Nov 15, 2018 at 05:02:31PM +0900, myungkyu.lim wrote:
>> I got confused by the field name. If we have 'last_msg_send_time'
>> field in pg_stat_replciation which has information of wal senders
>> users would think it as a time when the wal sender sent a message last
>> time. However values of the fields actually shows a time when the wal
>> receiver sent a reply message last time. So perhaps
>> 'last_reply_send_time' would be more clear.
>
> Good point. 'last_reply_send_time' is better.
> How about just 'reply_time'?

Please note that the original thread has mentioned reply_timestamp as a
consensus:
https://www.postgresql.org/message-id/CA%2BTgmoZ39FvwbVQGAusNx_Mv%3DyqOr_UFuFnMorNYNvxPaxkOeA%40mail.gmail.com
--
Michael

On Thu, Nov 15, 2018 at 5:27 PM Michael Paquier <michael@paquier.xyz> wrote:
>
> On Thu, Nov 15, 2018 at 05:02:31PM +0900, myungkyu.lim wrote:
> >> I got confused by the field name. If we have 'last_msg_send_time'
> >> field in pg_stat_replciation which has information of wal senders
> >> users would think it as a time when the wal sender sent a message last
> >> time. However values of the fields actually shows a time when the wal
> >> receiver sent a reply message last time. So perhaps
> >> 'last_reply_send_time' would be more clear.
> >
> > Good point. 'last_reply_send_time' is better.
> > How about just 'reply_time'?
>
> Please note that the original thread has mentioned reply_timestamp as a
> consensus:
> https://www.postgresql.org/message-id/CA%2BTgmoZ39FvwbVQGAusNx_Mv%3DyqOr_UFuFnMorNYNvxPaxkOeA%40mail.gmail.com

Yeah, I also agree with 'reply_time'. But please also note that we had
the discussion when there is not the similar system catalogs and
fields. Now that we have them it might be worth to consider to follow
the existing name for consistency.

Regards,

--
Masahiko Sawada
NIPPON TELEGRAPH AND TELEPHONE CORPORATION
NTT Open Source Software Center

On Thu, Nov 15, 2018 at 05:33:26PM +0900, Masahiko Sawada wrote:
> Yeah, I also agree with 'reply_time'. But please also note that we had
> the discussion when there is not the similar system catalogs and
> fields. Now that we have them it might be worth to consider to follow
> the existing name for consistency.

The fields in pg_stat_wal_receiver are named after their respective
fields.  Now if you look at the fields from pg_stat_replication, you
have those from the standby:
sent_lsn => Last write-ahead log location sent on this connection
write_lsn => Last write-ahead log location written to disk by this
standby server
flush_lsn => Last write-ahead log location flushed to disk by
this standby server
replay_lsn => Last write-ahead log location replayed into the
database on this standby server

So to keep the brand consistent, reply_time looks like the best choice
as Sawada-san suggests?
--
Michael

On Thu, Nov 15, 2018 at 5:27 PM Michael Paquier <michael@paquier.xyz> wrote:
>> Good point. 'last_reply_send_time' is better.
>> How about just 'reply_time'?
>
>Please note that the original thread has mentioned reply_timestamp as a
>consensus:

So I selected 'reply_time' because 'timestamp' was not used in stat field.

>On Thu, Nov 15, 2018 at 05:33:26PM +0900, Masahiko Sawada wrote:
>> Yeah, I also agree with 'reply_time'. But please also note that we had
>> the discussion when there is not the similar system catalogs and
>> fields. Now that we have them it might be worth to consider to follow
>> the existing name for consistency.
>
>The fields in pg_stat_wal_receiver are named after their respective fields.
>Now if you look at the fields from pg_stat_replication, you have those from
>the standby:
>sent_lsn => Last write-ahead log location sent on this connection write_lsn
>=> Last write-ahead log location written to disk by this standby server
>flush_lsn => Last write-ahead log location flushed to disk by this standby
>server replay_lsn => Last write-ahead log location replayed into the
>database on this standby server
>
>So to keep the brand consistent, reply_time looks like the best choice as
>Sawada-san suggests?

I agree.
The fields naming in pg_stat_replication are some different from other views
fields.
Not used 'last_' or 'latest_' prefix in fields.

Best regards,
Myungkyu, Lim

On Mon, Nov 26, 2018 at 02:48:39PM +0900, myungkyu.lim wrote:
> So I selected 'reply_time' because 'timestamp' was not used in stat
> field.

Fine by me.  Could you send a new patch please?  I am switching the
patch as waiting on author for now.
--
Michael

>On Mon, Nov 26, 2018 at 02:48:39PM +0900, myungkyu.lim wrote:
>> So I selected 'reply_time' because 'timestamp' was not used in stat
>> field.
>
>Fine by me.  Could you send a new patch please?  I am switching the patch
as
>waiting on author for now.

Ok.
Changed field name 'last_msg_send_time' to 'reply_time'.
Attached new patch file : 0001-Implement-following-TODO-list-item-v4.patch

example>
postgres=# select pid, reply_time from pg_stat_replication;
-[ RECORD 1 ]-----------------------------
pid        | 10493
reply_time | 2018-11-29 17:37:14.638428+09

check plz.

Best regards,
Myungkyu, Lim

On Thu, Nov 29, 2018 at 05:43:26PM +0900, myungkyu.lim wrote:
> Changed field name 'last_msg_send_time' to 'reply_time'.

Looks pretty to me at quick glance, unfortunately I have not spent much
time on it, particularly testing it.

+    <row>
+     <entry><structfield>reply_time</structfield></entry>
+     <entry><type>timestamp with time zone</type></entry>
+     <entry>Send time of last message received from WAL
receiver</entry>
+    </row>
This is a bit confusing as this counts for the last *standby* message
('r'), and not the last feedback message ('h').

+   /*
+    * timestamp of the latest message, reported by standby server
+   */
+   TimestampTz replyTime;

A small indentation problem, not a big deal.

Sawada-san, perhaps you would like to look at it?
--
Michael

On Fri, Nov 30, 2018 at 05:54:15PM +0900, Michael Paquier wrote:
> Looks pretty to me at quick glance, unfortunately I have not spent much
> time on it, particularly testing it.
>
> +    <row>
> +     <entry><structfield>reply_time</structfield></entry>
> +     <entry><type>timestamp with time zone</type></entry>
> +     <entry>Send time of last message received from WAL
> receiver</entry>
> +    </row>
> This is a bit confusing as this counts for the last *standby* message
> ('r'), and not the last feedback message ('h').
>
> +   /*
> +    * timestamp of the latest message, reported by standby server
> +   */
> +   TimestampTz replyTime;
>
> A small indentation problem, not a big deal.

I have been looking at this patch more in-depth, and you missed one
critical thing: hot standby feedback messages also include the timestamp
the client used when sending the message, so if we want to track the
latest time when a message has been sent we should track it as much as
the timestamp from status update messages.

Fixing that and updating a couple of comments and variables, I am
finishing with the attached.  Thoughts?

(The catversion bump is a self-reminder, don't worry about it.)
--
Michael

On Tue, Dec 04, 2018 at 12:56:25PM +0900, Michael Paquier wrote:
> I have been looking at this patch more in-depth, and you missed one
> critical thing: hot standby feedback messages also include the timestamp
> the client used when sending the message, so if we want to track the
> latest time when a message has been sent we should track it as much as
> the timestamp from status update messages.
>
> Fixing that and updating a couple of comments and variables, I am
> finishing with the attached.  Thoughts?
>
> (The catversion bump is a self-reminder, don't worry about it.)

Another thing which is crossing my mind is if it would make sense to
report the timestamp of the last HS feedback message and the timestamp
of the last status update message into two separate columns.  As the
point of this field is to help with the debugging of mostly idle systems
it seems to me that merging both is fine, but I'd like to hear extra
opinions about that.
--
Michael

>> I have been looking at this patch more in-depth, and you missed one
>> critical thing: hot standby feedback messages also include the
>> timestamp the client used when sending the message, so if we want to
>> track the latest time when a message has been sent we should track it
>> as much as the timestamp from status update messages.
>>
>> Fixing that and updating a couple of comments and variables, I am
>> finishing with the attached.  Thoughts?

Thanks! I missed it..:(

>Another thing which is crossing my mind is if it would make sense to report
>the timestamp of the last HS feedback message and the timestamp of the last
>status update message into two separate columns.  As the point of this
>field is to help with the debugging of mostly idle systems it seems to me
>that merging both is fine, but I'd like to hear extra opinions about that.

I think purpose of this field, 
that react interval check and debugging on idle system.
So, merging both is better.
(Is 'Reply' and 'HSFeedback' worth measuring separately?)

On Tue, Dec 04, 2018 at 04:24:25PM +0900, myungkyu.lim wrote:
> I think purpose of this field,
> that react interval check and debugging on idle system.
> So, merging both is better.

I have let this stuff cool down for a couple of days, still it seems to
me that having one single column makes the most sense when it comes when
looking at a mostly idle system.  I'll try to finish this one at the
beginning of next week, for now I am marking as ready for committer.
--
Michael

>I have let this stuff cool down for a couple of days, still it seems to me
>that having one single column makes the most sense when it comes when
>looking at a mostly idle system.  I'll try to finish this one at the
>beginning of next week, for now I am marking as ready for committer.

Thank you for your attention!

Best regards,
Myungkyu, Lim

On Fri, Dec 07, 2018 at 03:45:59PM +0900, myungkyu.lim wrote:
> Thank you for your attention!

And committed.  There was one thing that the patch was doing wrong:
there is no point to convert the timestamp to a string if no log message
is generated, so I have added a check on log_min_messages to avoid the
extra processing for normal workloads, and pushed.

Thanks for the patch, TODO_item--.
--
Michael