RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
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:mich...@paquier.xyz] Sent: Thursday, October 25, 2018 8:50 PM To: Laurenz Albe Cc: myungkyu@samsung.com; pgsql-hack...@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
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
Hi . On Tue, Jul 31, 2018 at 11:57 AM MyungKyu LIM wrote: > > Feedback and suggestion will be very welcome. > 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 . regards Surafel
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
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.55 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
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
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
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 signature.asc Description: PGP signature
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
On Thu, Nov 15, 2018 at 5:27 PM Michael Paquier 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
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 signature.asc Description: PGP signature
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
On Thu, Nov 15, 2018 at 5:27 PM Michael Paquier 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
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 signature.asc Description: PGP signature
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
>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 0001-Implement-following-TODO-list-item-v4.patch Description: Binary data
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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. + + reply_time + timestamp with time zone + Send time of last message received from WAL receiver + 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 signature.asc Description: PGP signature
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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. > > + > + reply_time > + timestamp with time zone > + Send time of last message received from WAL > receiver > + > 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 diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 7aada14417..22e93019a7 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -1920,6 +1920,11 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i + + reply_time + timestamp with time zone + Send time of last message received from standby server + diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 715995dd88..8630542bb3 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -734,7 +734,8 @@ CREATE VIEW pg_stat_replication AS W.flush_lag, W.replay_lag, W.sync_priority, -W.sync_state +W.sync_state, +W.reply_time FROM pg_stat_get_activity(NULL) AS S JOIN pg_stat_get_wal_senders() AS W ON (S.pid = W.pid) LEFT JOIN pg_authid AS U ON (S.usesysid = U.oid); diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c index 46edb525e8..11bdc741f0 100644 --- a/src/backend/replication/walsender.c +++ b/src/backend/replication/walsender.c @@ -1763,6 +1763,8 @@ ProcessStandbyReplyMessage(void) applyLag; bool clearLagTimes; TimestampTz now; + TimestampTz replyTime; + char *replyTimeStr; static bool fullyAppliedLastTime = false; @@ -1770,14 +1772,20 @@ ProcessStandbyReplyMessage(void) writePtr = pq_getmsgint64(&reply_message); flushPtr = pq_getmsgint64(&reply_message); applyPtr = pq_getmsgint64(&reply_message); - (void) pq_getmsgint64(&reply_message); /* sendTime; not used ATM */ + replyTime = pq_getmsgint64(&reply_message); replyRequested = pq_getmsgbyte(&reply_message); - elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s", + /* Copy because timestamptz_to_str returns a static buffer */ + replyTimeStr = pstrdup(timestamptz_to_str(replyTime)); + + elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s reply_time %s", (uint32) (writePtr >> 32), (uint32) writePtr, (uint32) (flushPtr >> 32), (uint32) flushPtr, (uint32) (applyPtr >> 32), (uint32) applyPtr, - replyRequested ? " (reply requested)" : ""); + replyRequested ? " (reply requested)" : "", + replyTimeStr); + + pfree(replyTimeStr); /* See if we can compute the round-trip lag for these positions. */ now = GetCurrentTimestamp(); @@ -1824,6 +1832,7 @@ ProcessStandbyReplyMessage(void) walsnd->flushLag = flushLag; if (applyLag != -1 || clearLagTimes) walsnd->applyLag = applyLag; + walsnd->replyTime = replyTime; SpinLockRelease(&walsnd->mutex); } @@ -1927,23 +1936,43 @@ ProcessStandbyHSFeedbackMessage(void) uint32 feedbackEpoch; TransactionId feedbackCatalogXmin; uint32 feedbackCatalogEpoch; + TimestampTz replyTime; + char *replyTimeStr; /* * Decipher the reply message. The caller already consumed the msgtype * byte. See XLogWalRcvSendHSFeedback() in walreceiver.c for the creation * of this message. */ - (void) pq_getmsgint64(&reply_message); /* sendTime; not used ATM */ + replyTime = pq_getmsgint64(&reply_message); feedbackXmin = pq_getmsgint(&reply_message, 4); feedbackEpoch = pq_getmsgint(&reply_message, 4); feedbackCatalogXmin = pq_getmsgint(&reply_message, 4); feedbackCatalogEpoch = pq_getmsgint(&reply_message, 4); - elog(DEBUG2, "hot standby feedback xmin %u epoch %u, catalog_xmin %u epoch %u", + /* Copy because timestamptz_to_str returns a static buffer */ + replyTimeStr = pstrdup(timestamptz_to_str(replyTime)); + + elog(DEBUG2, "hot standby feedback xmin %u epoch %u, catalog_xmin %u epoch %u reply_time %s", feedbackXmin, feedbackEpoch, feedbackCatalogXmin, - feedbackCatalogEpoch); + feedbackCatalogEpoch, + replyTimeStr); + + pfree(replyTimeStr); + + /* + * Up
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 signature.asc Description: PGP signature
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
>> 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?)
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 signature.asc Description: PGP signature
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
>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
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 signature.asc Description: PGP signature
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
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication
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 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 0001-Implement-following-TODO-list-item-v3.patch Description: Binary data