[Todo item] Add entry creation timestamp column to pg_stat_replication

Started by MyungKyu LIMover 7 years ago22 messages
#1MyungKyu LIM
myungkyu.lim@samsung.com
1 attachment(s)

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

Attachments:

0001-Implement-following-TODO-list-item.patchapplication/octet-streamDownload
From 62a8f97e7362f470ab38c75c36292384fd86d8df Mon Sep 17 00:00:00 2001
From: "MyungKyu, Lim" <myungkyu.lim@samsung.com>
Date: Tue, 31 Jul 2018 12:03:15 +0900
Subject: [PATCH] Implement following TODO list item

   : Add entry creation timestamp column to pg_stat_replication
       mailing list : http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
---
 src/backend/catalog/system_views.sql        |  3 ++-
 src/backend/replication/walsender.c         | 25 +++++++++++++++++++++----
 src/include/catalog/pg_proc.dat             |  6 +++---
 src/include/replication/walsender_private.h |  5 +++++
 src/test/regress/expected/rules.out         |  5 +++--
 5 files changed, 34 insertions(+), 10 deletions(-)

diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 7251552..eef834b 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 d60026d..e8a33a3 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1772,6 +1772,8 @@ ProcessStandbyReplyMessage(void)
 				applyLag;
 	bool		clearLagTimes;
 	TimestampTz now;
+	TimestampTz	reply_timestamp;
+	char	   *replytime;
 
 	static bool fullyAppliedLastTime = false;
 
@@ -1779,14 +1781,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 */
+	reply_timestamp = pq_getmsgint64(&reply_message);	/* sendTime */
 	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 */
+	replytime = pstrdup(timestamptz_to_str(reply_timestamp));
+
+	elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s replytime %s",
 		 (uint32) (writePtr >> 32), (uint32) writePtr,
 		 (uint32) (flushPtr >> 32), (uint32) flushPtr,
 		 (uint32) (applyPtr >> 32), (uint32) applyPtr,
-		 replyRequested ? " (reply requested)" : "");
+		 replyRequested ? " (reply requested)" : "",
+		 replytime);
+
+	pfree(replytime);
 
 	/* See if we can compute the round-trip lag for these positions. */
 	now = GetCurrentTimestamp();
@@ -1833,6 +1841,7 @@ ProcessStandbyReplyMessage(void)
 			walsnd->flushLag = flushLag;
 		if (applyLag != -1 || clearLagTimes)
 			walsnd->applyLag = applyLag;
+		walsnd->reply_timestamp = reply_timestamp;
 		SpinLockRelease(&walsnd->mutex);
 	}
 
@@ -2273,6 +2282,7 @@ InitWalSenderSlot(void)
 			walsnd->applyLag = -1;
 			walsnd->state = WALSNDSTATE_STARTUP;
 			walsnd->latch = &MyProc->procLatch;
+			walsnd->reply_timestamp = 0;
 			SpinLockRelease(&walsnd->mutex);
 			/* don't need the lock anymore */
 			MyWalSnd = (WalSnd *) walsnd;
@@ -3191,7 +3201,7 @@ offset_to_interval(TimeOffset offset)
 Datum
 pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_SENDERS_COLS	11
+#define PG_STAT_GET_WAL_SENDERS_COLS	12
 	ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
 	TupleDesc	tupdesc;
 	Tuplestorestate *tupstore;
@@ -3245,6 +3255,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		int			priority;
 		int			pid;
 		WalSndState state;
+		TimestampTz	reply_timestamp;
 		Datum		values[PG_STAT_GET_WAL_SENDERS_COLS];
 		bool		nulls[PG_STAT_GET_WAL_SENDERS_COLS];
 
@@ -3264,6 +3275,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		flushLag = walsnd->flushLag;
 		applyLag = walsnd->applyLag;
 		priority = walsnd->sync_standby_priority;
+		reply_timestamp = walsnd->reply_timestamp;
 		SpinLockRelease(&walsnd->mutex);
 
 		memset(nulls, 0, sizeof(nulls));
@@ -3340,6 +3352,11 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 					CStringGetTextDatum("sync") : CStringGetTextDatum("quorum");
 			else
 				values[10] = CStringGetTextDatum("potential");
+
+			if (reply_timestamp == 0)
+				nulls[11] = true;
+			else
+				values[11] = TimestampTzGetDatum(reply_timestamp);
 		}
 
 		tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index a146510..ef262a2 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5181,9 +5181,9 @@
   proname => 'pg_stat_get_wal_senders', prorows => '10', proisstrict => 'f',
   proretset => 't', provolatile => 's', proparallel => 'r',
   prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
-  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state}',
+  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text,timestamptz}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state,reply_time}',
   prosrc => 'pg_stat_get_wal_senders' },
 { oid => '3317', descr => 'statistics: information about WAL receiver',
   proname => 'pg_stat_get_wal_receiver', proisstrict => 'f', provolatile => 's',
diff --git a/src/include/replication/walsender_private.h b/src/include/replication/walsender_private.h
index 4b90477..dc53314 100644
--- a/src/include/replication/walsender_private.h
+++ b/src/include/replication/walsender_private.h
@@ -75,6 +75,11 @@ typedef struct WalSnd
 	 * SyncRepLock.
 	 */
 	int			sync_standby_priority;
+
+	/*
+	 * The timestamp of reply message when created by the standby.
+	*/
+	TimestampTz	reply_timestamp;
 } WalSnd;
 
 extern WalSnd *MyWalSnd;
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 744d501..6fa62d0 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1861,9 +1861,10 @@ pg_stat_replication| SELECT s.pid,
     w.flush_lag,
     w.replay_lag,
     w.sync_priority,
-    w.sync_state
+    w.sync_state,
+    w.reply_time
    FROM ((pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, wait_event_type, wait_event, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port, backend_xid, backend_xmin, backend_type, ssl, sslversion, sslcipher, sslbits, sslcompression, sslclientdn)
-     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state) ON ((s.pid = w.pid)))
+     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state, reply_time) ON ((s.pid = w.pid)))
      LEFT JOIN pg_authid u ON ((s.usesysid = u.oid)));
 pg_stat_ssl| SELECT s.pid,
     s.ssl,
-- 
1.8.3.1

#2MyungKyu LIM
myungkyu.lim@samsung.com
In reply to: MyungKyu LIM (#1)
2 attachment(s)
FW: [Todo item] Add entry creation timestamp column to pg_stat_replication

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

Attachments:

0001-Implement-following-TODO-list-item-v1.patchapplication/octet-streamDownload
From 62a8f97e7362f470ab38c75c36292384fd86d8df Mon Sep 17 00:00:00 2001
From: "MyungKyu, Lim" <myungkyu.lim@samsung.com>
Date: Tue, 31 Jul 2018 12:03:15 +0900
Subject: [PATCH] Implement following TODO list item

   : Add entry creation timestamp column to pg_stat_replication
       mailing list : http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
---
 src/backend/catalog/system_views.sql        |  3 ++-
 src/backend/replication/walsender.c         | 25 +++++++++++++++++++++----
 src/include/catalog/pg_proc.dat             |  6 +++---
 src/include/replication/walsender_private.h |  5 +++++
 src/test/regress/expected/rules.out         |  5 +++--
 5 files changed, 34 insertions(+), 10 deletions(-)

diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 7251552..eef834b 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 d60026d..e8a33a3 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1772,6 +1772,8 @@ ProcessStandbyReplyMessage(void)
 				applyLag;
 	bool		clearLagTimes;
 	TimestampTz now;
+	TimestampTz	reply_timestamp;
+	char	   *replytime;
 
 	static bool fullyAppliedLastTime = false;
 
@@ -1779,14 +1781,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 */
+	reply_timestamp = pq_getmsgint64(&reply_message);	/* sendTime */
 	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 */
+	replytime = pstrdup(timestamptz_to_str(reply_timestamp));
+
+	elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s replytime %s",
 		 (uint32) (writePtr >> 32), (uint32) writePtr,
 		 (uint32) (flushPtr >> 32), (uint32) flushPtr,
 		 (uint32) (applyPtr >> 32), (uint32) applyPtr,
-		 replyRequested ? " (reply requested)" : "");
+		 replyRequested ? " (reply requested)" : "",
+		 replytime);
+
+	pfree(replytime);
 
 	/* See if we can compute the round-trip lag for these positions. */
 	now = GetCurrentTimestamp();
@@ -1833,6 +1841,7 @@ ProcessStandbyReplyMessage(void)
 			walsnd->flushLag = flushLag;
 		if (applyLag != -1 || clearLagTimes)
 			walsnd->applyLag = applyLag;
+		walsnd->reply_timestamp = reply_timestamp;
 		SpinLockRelease(&walsnd->mutex);
 	}
 
@@ -2273,6 +2282,7 @@ InitWalSenderSlot(void)
 			walsnd->applyLag = -1;
 			walsnd->state = WALSNDSTATE_STARTUP;
 			walsnd->latch = &MyProc->procLatch;
+			walsnd->reply_timestamp = 0;
 			SpinLockRelease(&walsnd->mutex);
 			/* don't need the lock anymore */
 			MyWalSnd = (WalSnd *) walsnd;
@@ -3191,7 +3201,7 @@ offset_to_interval(TimeOffset offset)
 Datum
 pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_SENDERS_COLS	11
+#define PG_STAT_GET_WAL_SENDERS_COLS	12
 	ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
 	TupleDesc	tupdesc;
 	Tuplestorestate *tupstore;
@@ -3245,6 +3255,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		int			priority;
 		int			pid;
 		WalSndState state;
+		TimestampTz	reply_timestamp;
 		Datum		values[PG_STAT_GET_WAL_SENDERS_COLS];
 		bool		nulls[PG_STAT_GET_WAL_SENDERS_COLS];
 
@@ -3264,6 +3275,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		flushLag = walsnd->flushLag;
 		applyLag = walsnd->applyLag;
 		priority = walsnd->sync_standby_priority;
+		reply_timestamp = walsnd->reply_timestamp;
 		SpinLockRelease(&walsnd->mutex);
 
 		memset(nulls, 0, sizeof(nulls));
@@ -3340,6 +3352,11 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 					CStringGetTextDatum("sync") : CStringGetTextDatum("quorum");
 			else
 				values[10] = CStringGetTextDatum("potential");
+
+			if (reply_timestamp == 0)
+				nulls[11] = true;
+			else
+				values[11] = TimestampTzGetDatum(reply_timestamp);
 		}
 
 		tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index a146510..ef262a2 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5181,9 +5181,9 @@
   proname => 'pg_stat_get_wal_senders', prorows => '10', proisstrict => 'f',
   proretset => 't', provolatile => 's', proparallel => 'r',
   prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
-  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state}',
+  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text,timestamptz}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state,reply_time}',
   prosrc => 'pg_stat_get_wal_senders' },
 { oid => '3317', descr => 'statistics: information about WAL receiver',
   proname => 'pg_stat_get_wal_receiver', proisstrict => 'f', provolatile => 's',
diff --git a/src/include/replication/walsender_private.h b/src/include/replication/walsender_private.h
index 4b90477..dc53314 100644
--- a/src/include/replication/walsender_private.h
+++ b/src/include/replication/walsender_private.h
@@ -75,6 +75,11 @@ typedef struct WalSnd
 	 * SyncRepLock.
 	 */
 	int			sync_standby_priority;
+
+	/*
+	 * The timestamp of reply message when created by the standby.
+	*/
+	TimestampTz	reply_timestamp;
 } WalSnd;
 
 extern WalSnd *MyWalSnd;
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 744d501..6fa62d0 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1861,9 +1861,10 @@ pg_stat_replication| SELECT s.pid,
     w.flush_lag,
     w.replay_lag,
     w.sync_priority,
-    w.sync_state
+    w.sync_state,
+    w.reply_time
    FROM ((pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, wait_event_type, wait_event, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port, backend_xid, backend_xmin, backend_type, ssl, sslversion, sslcipher, sslbits, sslcompression, sslclientdn)
-     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state) ON ((s.pid = w.pid)))
+     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state, reply_time) ON ((s.pid = w.pid)))
      LEFT JOIN pg_authid u ON ((s.usesysid = u.oid)));
 pg_stat_ssl| SELECT s.pid,
     s.ssl,
-- 
1.8.3.1

0001-Implement-following-TODO-list-item-v2.patchapplication/octet-streamDownload
From 62920acda9a9fd96d564d9ca02965e8653e2be98 Mon Sep 17 00:00:00 2001
From: "MyungKyu, Lim" <myungkyu.lim@samsung.com>
Date: Thu, 2 Aug 2018 18:05:19 +0900
Subject: [PATCH] Implement following TODO list item

  : Add entry creation timestamp column to pg_stat_replication
    mailing list : http://archives.postgresql.org/pgsql-hackers/2011-08/msg00694.php
---
 src/backend/catalog/system_views.sql        |  3 ++-
 src/backend/replication/walsender.c         | 25 +++++++++++++++++++++----
 src/include/catalog/pg_proc.dat             |  6 +++---
 src/include/replication/walsender_private.h |  5 +++++
 src/test/regress/expected/rules.out         |  5 +++--
 5 files changed, 34 insertions(+), 10 deletions(-)

diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 7251552..4e30eeb 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.last_msg_send_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 c83ff3b..a241ec6 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1775,6 +1775,8 @@ ProcessStandbyReplyMessage(void)
 				applyLag;
 	bool		clearLagTimes;
 	TimestampTz now;
+	TimestampTz	sendTimestamp;
+	char	   *sendTime;
 
 	static bool fullyAppliedLastTime = false;
 
@@ -1782,14 +1784,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 */
+	sendTimestamp = pq_getmsgint64(&reply_message);	/* sendTime */
 	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 */
+	sendTime = pstrdup(timestamptz_to_str(sendTimestamp));
+
+	elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s replytime %s",
 		 (uint32) (writePtr >> 32), (uint32) writePtr,
 		 (uint32) (flushPtr >> 32), (uint32) flushPtr,
 		 (uint32) (applyPtr >> 32), (uint32) applyPtr,
-		 replyRequested ? " (reply requested)" : "");
+		 replyRequested ? " (reply requested)" : "",
+		 sendTime);
+
+	pfree(sendTime);
 
 	/* See if we can compute the round-trip lag for these positions. */
 	now = GetCurrentTimestamp();
@@ -1836,6 +1844,7 @@ ProcessStandbyReplyMessage(void)
 			walsnd->flushLag = flushLag;
 		if (applyLag != -1 || clearLagTimes)
 			walsnd->applyLag = applyLag;
+		walsnd->lastMsgSendTime = sendTimestamp;
 		SpinLockRelease(&walsnd->mutex);
 	}
 
@@ -2276,6 +2285,7 @@ InitWalSenderSlot(void)
 			walsnd->applyLag = -1;
 			walsnd->state = WALSNDSTATE_STARTUP;
 			walsnd->latch = &MyProc->procLatch;
+			walsnd->lastMsgSendTime = 0;
 			SpinLockRelease(&walsnd->mutex);
 			/* don't need the lock anymore */
 			MyWalSnd = (WalSnd *) walsnd;
@@ -3194,7 +3204,7 @@ offset_to_interval(TimeOffset offset)
 Datum
 pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_SENDERS_COLS	11
+#define PG_STAT_GET_WAL_SENDERS_COLS	12
 	ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
 	TupleDesc	tupdesc;
 	Tuplestorestate *tupstore;
@@ -3248,6 +3258,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		int			priority;
 		int			pid;
 		WalSndState state;
+		TimestampTz	last_send_time;
 		Datum		values[PG_STAT_GET_WAL_SENDERS_COLS];
 		bool		nulls[PG_STAT_GET_WAL_SENDERS_COLS];
 
@@ -3267,6 +3278,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		flushLag = walsnd->flushLag;
 		applyLag = walsnd->applyLag;
 		priority = walsnd->sync_standby_priority;
+		last_send_time = walsnd->lastMsgSendTime;
 		SpinLockRelease(&walsnd->mutex);
 
 		memset(nulls, 0, sizeof(nulls));
@@ -3343,6 +3355,11 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 					CStringGetTextDatum("sync") : CStringGetTextDatum("quorum");
 			else
 				values[10] = CStringGetTextDatum("potential");
+
+			if (last_send_time == 0)
+				nulls[11] = true;
+			else
+				values[11] = TimestampTzGetDatum(last_send_time);
 		}
 
 		tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index a146510..d09533c 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5181,9 +5181,9 @@
   proname => 'pg_stat_get_wal_senders', prorows => '10', proisstrict => 'f',
   proretset => 't', provolatile => 's', proparallel => 'r',
   prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
-  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state}',
+  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text,timestamptz}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state,last_msg_send_time}',
   prosrc => 'pg_stat_get_wal_senders' },
 { oid => '3317', descr => 'statistics: information about WAL receiver',
   proname => 'pg_stat_get_wal_receiver', proisstrict => 'f', provolatile => 's',
diff --git a/src/include/replication/walsender_private.h b/src/include/replication/walsender_private.h
index 4b90477..057bcb4 100644
--- a/src/include/replication/walsender_private.h
+++ b/src/include/replication/walsender_private.h
@@ -75,6 +75,11 @@ typedef struct WalSnd
 	 * SyncRepLock.
 	 */
 	int			sync_standby_priority;
+
+	/*
+	 * timestamp of the latest message, reported by standby server
+	*/
+	TimestampTz	lastMsgSendTime;
 } WalSnd;
 
 extern WalSnd *MyWalSnd;
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 078129f..40220cb 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1861,9 +1861,10 @@ pg_stat_replication| SELECT s.pid,
     w.flush_lag,
     w.replay_lag,
     w.sync_priority,
-    w.sync_state
+    w.sync_state,
+    w.last_msg_send_time
    FROM ((pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, wait_event_type, wait_event, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port, backend_xid, backend_xmin, backend_type, ssl, sslversion, sslcipher, sslbits, sslcompression, sslclientdn)
-     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state) ON ((s.pid = w.pid)))
+     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state, last_msg_send_time) ON ((s.pid = w.pid)))
      LEFT JOIN pg_authid u ON ((s.usesysid = u.oid)));
 pg_stat_ssl| SELECT s.pid,
     s.ssl,
-- 
1.8.3.1

#3Laurenz Albe
laurenz.albe@cybertec.at
In reply to: MyungKyu LIM (#1)
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

#4MyungKyu LIM
myungkyu.lim@samsung.com
In reply to: Laurenz Albe (#3)
1 attachment(s)
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 <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
 
 
 

Attachments:

0001-Implement-following-TODO-list-item-v3.patchapplication/octet-streamDownload
From addffcd2dd6e69e534a3f2bd903986498ae58ff4 Mon Sep 17 00:00:00 2001
From: "MyungKyu, Lim" <myungkyu.lim@samsung.com>
Date: Thu, 25 Oct 2018 16:09:29 +0900
Subject: [PATCH] Implement following TODO list item

  : Add entry creation timestamp column to pg_stat_replication
    mailing list : https://www.postgresql.org/message-id/flat/1657809367.407321.1533027417725.JavaMail.jboss%40ep2ml404
    todo page : https://wiki.postgresql.org/wiki/Todo#Monitoring
---
 doc/src/sgml/monitoring.sgml                |  5 +++++
 src/backend/catalog/system_views.sql        |  3 ++-
 src/backend/replication/walsender.c         | 25 +++++++++++++++++++++----
 src/include/catalog/pg_proc.dat             |  6 +++---
 src/include/replication/walsender_private.h |  5 +++++
 src/test/regress/expected/rules.out         |  5 +++--
 6 files changed, 39 insertions(+), 10 deletions(-)

diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index add7145..4fadd1c 100644
--- a/doc/src/sgml/monitoring.sgml
+++ b/doc/src/sgml/monitoring.sgml
@@ -1916,6 +1916,11 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i
        </itemizedlist>
      </entry>
     </row>
+    <row>
+     <entry><structfield>last_msg_send_time</structfield></entry>
+     <entry><type>timestamp with time zone</type></entry>
+     <entry>Send time of last message received from WAL receiver</entry>
+    </row>
    </tbody>
    </tgroup>
   </table>
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 53ddc59..5179234 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.last_msg_send_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 2683385..0f2af3f 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1777,6 +1777,8 @@ ProcessStandbyReplyMessage(void)
 				applyLag;
 	bool		clearLagTimes;
 	TimestampTz now;
+	TimestampTz	sendTimestamp;
+	char	   *sendTime;
 
 	static bool fullyAppliedLastTime = false;
 
@@ -1784,14 +1786,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 */
+	sendTimestamp = pq_getmsgint64(&reply_message);	/* sendTime */
 	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 */
+	sendTime = pstrdup(timestamptz_to_str(sendTimestamp));
+
+	elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s replytime %s",
 		 (uint32) (writePtr >> 32), (uint32) writePtr,
 		 (uint32) (flushPtr >> 32), (uint32) flushPtr,
 		 (uint32) (applyPtr >> 32), (uint32) applyPtr,
-		 replyRequested ? " (reply requested)" : "");
+		 replyRequested ? " (reply requested)" : "",
+		 sendTime);
+
+	pfree(sendTime);
 
 	/* See if we can compute the round-trip lag for these positions. */
 	now = GetCurrentTimestamp();
@@ -1838,6 +1846,7 @@ ProcessStandbyReplyMessage(void)
 			walsnd->flushLag = flushLag;
 		if (applyLag != -1 || clearLagTimes)
 			walsnd->applyLag = applyLag;
+		walsnd->lastMsgSendTime = sendTimestamp;
 		SpinLockRelease(&walsnd->mutex);
 	}
 
@@ -2286,6 +2295,7 @@ InitWalSenderSlot(void)
 			walsnd->applyLag = -1;
 			walsnd->state = WALSNDSTATE_STARTUP;
 			walsnd->latch = &MyProc->procLatch;
+			walsnd->lastMsgSendTime = 0;
 			SpinLockRelease(&walsnd->mutex);
 			/* don't need the lock anymore */
 			MyWalSnd = (WalSnd *) walsnd;
@@ -3204,7 +3214,7 @@ offset_to_interval(TimeOffset offset)
 Datum
 pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_SENDERS_COLS	11
+#define PG_STAT_GET_WAL_SENDERS_COLS	12
 	ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
 	TupleDesc	tupdesc;
 	Tuplestorestate *tupstore;
@@ -3258,6 +3268,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		int			priority;
 		int			pid;
 		WalSndState state;
+		TimestampTz	last_send_time;
 		Datum		values[PG_STAT_GET_WAL_SENDERS_COLS];
 		bool		nulls[PG_STAT_GET_WAL_SENDERS_COLS];
 
@@ -3277,6 +3288,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		flushLag = walsnd->flushLag;
 		applyLag = walsnd->applyLag;
 		priority = walsnd->sync_standby_priority;
+		last_send_time = walsnd->lastMsgSendTime;
 		SpinLockRelease(&walsnd->mutex);
 
 		memset(nulls, 0, sizeof(nulls));
@@ -3353,6 +3365,11 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 					CStringGetTextDatum("sync") : CStringGetTextDatum("quorum");
 			else
 				values[10] = CStringGetTextDatum("potential");
+
+			if (last_send_time == 0)
+				nulls[11] = true;
+			else
+				values[11] = TimestampTzGetDatum(last_send_time);
 		}
 
 		tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 4d7fe1b..c717409 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5014,9 +5014,9 @@
   proname => 'pg_stat_get_wal_senders', prorows => '10', proisstrict => 'f',
   proretset => 't', provolatile => 's', proparallel => 'r',
   prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
-  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state}',
+  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text,timestamptz}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state,last_msg_send_time}',
   prosrc => 'pg_stat_get_wal_senders' },
 { oid => '3317', descr => 'statistics: information about WAL receiver',
   proname => 'pg_stat_get_wal_receiver', proisstrict => 'f', provolatile => 's',
diff --git a/src/include/replication/walsender_private.h b/src/include/replication/walsender_private.h
index 4b90477..057bcb4 100644
--- a/src/include/replication/walsender_private.h
+++ b/src/include/replication/walsender_private.h
@@ -75,6 +75,11 @@ typedef struct WalSnd
 	 * SyncRepLock.
 	 */
 	int			sync_standby_priority;
+
+	/*
+	 * timestamp of the latest message, reported by standby server
+	*/
+	TimestampTz	lastMsgSendTime;
 } WalSnd;
 
 extern WalSnd *MyWalSnd;
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 735dd37..9037681 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1861,9 +1861,10 @@ pg_stat_replication| SELECT s.pid,
     w.flush_lag,
     w.replay_lag,
     w.sync_priority,
-    w.sync_state
+    w.sync_state,
+    w.last_msg_send_time
    FROM ((pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, wait_event_type, wait_event, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port, backend_xid, backend_xmin, backend_type, ssl, sslversion, sslcipher, sslbits, sslcompression, sslclientdn)
-     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state) ON ((s.pid = w.pid)))
+     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state, last_msg_send_time) ON ((s.pid = w.pid)))
      LEFT JOIN pg_authid u ON ((s.usesysid = u.oid)));
 pg_stat_ssl| SELECT s.pid,
     s.ssl,
-- 
1.8.3.1

#5MyungKyu LIM
myungkyu.lim@samsung.com
In reply to: MyungKyu LIM (#4)
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: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.

/messages/by-id/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

#6Surafel Temesgen
surafel3000@gmail.com
In reply to: MyungKyu LIM (#1)
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication

Hi .
On Tue, Jul 31, 2018 at 11:57 AM MyungKyu LIM <myungkyu.lim@samsung.com>
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

#7myungkyu.lim
myungkyu.lim@samsung.com
In reply to: Surafel Temesgen (#6)
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.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

#8Masahiko Sawada
sawada.mshk@gmail.com
In reply to: MyungKyu LIM (#2)
Re: FW: [Todo item] Add entry creation timestamp column to pg_stat_replication

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

#9myungkyu.lim
myungkyu.lim@samsung.com
In reply to: myungkyu.lim (#7)
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

#10Michael Paquier
michael@paquier.xyz
In reply to: myungkyu.lim (#9)
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:
/messages/by-id/CA+TgmoZ39FvwbVQGAusNx_Mv=yqOr_UFuFnMorNYNvxPaxkOeA@mail.gmail.com
--
Michael

#11Masahiko Sawada
sawada.mshk@gmail.com
In reply to: Michael Paquier (#10)
Re: [Todo item] Add entry creation timestamp column to pg_stat_replication

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:
/messages/by-id/CA+TgmoZ39FvwbVQGAusNx_Mv=yqOr_UFuFnMorNYNvxPaxkOeA@mail.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

#12Michael Paquier
michael@paquier.xyz
In reply to: Masahiko Sawada (#11)
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

#13myungkyu.lim
myungkyu.lim@samsung.com
In reply to: Michael Paquier (#12)
RE: [Todo item] Add entry creation timestamp column to pg_stat_replication

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

#14Michael Paquier
michael@paquier.xyz
In reply to: myungkyu.lim (#13)
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

#15myungkyu.lim
myungkyu.lim@samsung.com
In reply to: Michael Paquier (#14)
1 attachment(s)
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

Attachments:

0001-Implement-following-TODO-list-item-v4.patchapplication/octet-stream; name=0001-Implement-following-TODO-list-item-v4.patchDownload
From 93a81fece48acd8e678393b852dc819a4277cc16 Mon Sep 17 00:00:00 2001
From: "MyungKyu, Lim" <myungkyu.lim@samsung.com>
Date: Thu, 29 Nov 2018 17:29:10 +0900
Subject: [PATCH] [PATCH] Implement following TODO list item

  : Add entry creation timestamp column to pg_stat_replication
    mailing list : https://www.postgresql.org/message-id/flat/1657809367.407321.1533027417725.JavaMail.jboss%40ep2ml404
    todo page : https://wiki.postgresql.org/wiki/Todo#Monitoring
---
 doc/src/sgml/monitoring.sgml                |  5 +++++
 src/backend/catalog/system_views.sql        |  3 ++-
 src/backend/replication/walsender.c         | 25 +++++++++++++++++++++----
 src/include/catalog/pg_proc.dat             |  6 +++---
 src/include/replication/walsender_private.h |  5 +++++
 src/test/regress/expected/rules.out         |  5 +++--
 6 files changed, 39 insertions(+), 10 deletions(-)

diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml
index 7aada14..0d8d35b 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
        </itemizedlist>
      </entry>
     </row>
+    <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>
    </tbody>
    </tgroup>
   </table>
diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql
index 715995d..8630542 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 46edb52..3bf0c58 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	sendTimestamp;
+	char	   *sendTime;
 
 	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 */
+	sendTimestamp = pq_getmsgint64(&reply_message);	/* sendtime by standby  */
 	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 */
+	sendTime = pstrdup(timestamptz_to_str(sendTimestamp));
+
+	elog(DEBUG2, "write %X/%X flush %X/%X apply %X/%X%s replytime %s",
 		 (uint32) (writePtr >> 32), (uint32) writePtr,
 		 (uint32) (flushPtr >> 32), (uint32) flushPtr,
 		 (uint32) (applyPtr >> 32), (uint32) applyPtr,
-		 replyRequested ? " (reply requested)" : "");
+		 replyRequested ? " (reply requested)" : "",
+		 sendTime);
+
+	pfree(sendTime);
 
 	/* 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 = sendTimestamp;
 		SpinLockRelease(&walsnd->mutex);
 	}
 
@@ -2265,6 +2274,7 @@ InitWalSenderSlot(void)
 			walsnd->applyLag = -1;
 			walsnd->state = WALSNDSTATE_STARTUP;
 			walsnd->latch = &MyProc->procLatch;
+			walsnd->replyTime = 0;
 			SpinLockRelease(&walsnd->mutex);
 			/* don't need the lock anymore */
 			MyWalSnd = (WalSnd *) walsnd;
@@ -3179,7 +3189,7 @@ offset_to_interval(TimeOffset offset)
 Datum
 pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_SENDERS_COLS	11
+#define PG_STAT_GET_WAL_SENDERS_COLS	12
 	ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
 	TupleDesc	tupdesc;
 	Tuplestorestate *tupstore;
@@ -3233,6 +3243,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		int			priority;
 		int			pid;
 		WalSndState state;
+		TimestampTz	replyTime;
 		Datum		values[PG_STAT_GET_WAL_SENDERS_COLS];
 		bool		nulls[PG_STAT_GET_WAL_SENDERS_COLS];
 
@@ -3252,6 +3263,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		flushLag = walsnd->flushLag;
 		applyLag = walsnd->applyLag;
 		priority = walsnd->sync_standby_priority;
+		replyTime = walsnd->replyTime;
 		SpinLockRelease(&walsnd->mutex);
 
 		memset(nulls, 0, sizeof(nulls));
@@ -3328,6 +3340,11 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 					CStringGetTextDatum("sync") : CStringGetTextDatum("quorum");
 			else
 				values[10] = CStringGetTextDatum("potential");
+
+			if (replyTime == 0)
+				nulls[11] = true;
+			else
+				values[11] = TimestampTzGetDatum(replyTime);
 		}
 
 		tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 034a41e..f79fcfe 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5023,9 +5023,9 @@
   proname => 'pg_stat_get_wal_senders', prorows => '10', proisstrict => 'f',
   proretset => 't', provolatile => 's', proparallel => 'r',
   prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
-  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state}',
+  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text,timestamptz}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state,reply_time}',
   prosrc => 'pg_stat_get_wal_senders' },
 { oid => '3317', descr => 'statistics: information about WAL receiver',
   proname => 'pg_stat_get_wal_receiver', proisstrict => 'f', provolatile => 's',
diff --git a/src/include/replication/walsender_private.h b/src/include/replication/walsender_private.h
index 4b90477..73a09a6 100644
--- a/src/include/replication/walsender_private.h
+++ b/src/include/replication/walsender_private.h
@@ -75,6 +75,11 @@ typedef struct WalSnd
 	 * SyncRepLock.
 	 */
 	int			sync_standby_priority;
+
+	/*
+	 * timestamp of the latest message, reported by standby server
+	*/
+	TimestampTz	replyTime;
 } WalSnd;
 
 extern WalSnd *MyWalSnd;
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 735dd37..b68b8d2 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1861,9 +1861,10 @@ pg_stat_replication| SELECT s.pid,
     w.flush_lag,
     w.replay_lag,
     w.sync_priority,
-    w.sync_state
+    w.sync_state,
+    w.reply_time
    FROM ((pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, wait_event_type, wait_event, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port, backend_xid, backend_xmin, backend_type, ssl, sslversion, sslcipher, sslbits, sslcompression, sslclientdn)
-     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state) ON ((s.pid = w.pid)))
+     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state, reply_time) ON ((s.pid = w.pid)))
      LEFT JOIN pg_authid u ON ((s.usesysid = u.oid)));
 pg_stat_ssl| SELECT s.pid,
     s.ssl,
-- 
1.8.3.1

#16Michael Paquier
michael@paquier.xyz
In reply to: myungkyu.lim (#15)
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.

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

#17Michael Paquier
michael@paquier.xyz
In reply to: Michael Paquier (#16)
1 attachment(s)
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.

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

Attachments:

standby-message-time-v3.patchtext/x-diff; charset=us-asciiDownload
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
        </itemizedlist>
      </entry>
     </row>
+    <row>
+     <entry><structfield>reply_time</structfield></entry>
+     <entry><type>timestamp with time zone</type></entry>
+     <entry>Send time of last message received from standby server</entry>
+    </row>
    </tbody>
    </tgroup>
   </table>
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);
+
+	/*
+	 * Update shared state for this WalSender process based on reply data from
+	 * standby.
+	 */
+	{
+		WalSnd	   *walsnd = MyWalSnd;
+
+		SpinLockAcquire(&walsnd->mutex);
+		walsnd->replyTime = replyTime;
+		SpinLockRelease(&walsnd->mutex);
+	}
 
 	/*
 	 * Unset WalSender's xmins if the feedback message values are invalid.
@@ -2265,6 +2294,7 @@ InitWalSenderSlot(void)
 			walsnd->applyLag = -1;
 			walsnd->state = WALSNDSTATE_STARTUP;
 			walsnd->latch = &MyProc->procLatch;
+			walsnd->replyTime = 0;
 			SpinLockRelease(&walsnd->mutex);
 			/* don't need the lock anymore */
 			MyWalSnd = (WalSnd *) walsnd;
@@ -3179,7 +3209,7 @@ offset_to_interval(TimeOffset offset)
 Datum
 pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 {
-#define PG_STAT_GET_WAL_SENDERS_COLS	11
+#define PG_STAT_GET_WAL_SENDERS_COLS	12
 	ReturnSetInfo *rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
 	TupleDesc	tupdesc;
 	Tuplestorestate *tupstore;
@@ -3233,6 +3263,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		int			priority;
 		int			pid;
 		WalSndState state;
+		TimestampTz	replyTime;
 		Datum		values[PG_STAT_GET_WAL_SENDERS_COLS];
 		bool		nulls[PG_STAT_GET_WAL_SENDERS_COLS];
 
@@ -3252,6 +3283,7 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 		flushLag = walsnd->flushLag;
 		applyLag = walsnd->applyLag;
 		priority = walsnd->sync_standby_priority;
+		replyTime = walsnd->replyTime;
 		SpinLockRelease(&walsnd->mutex);
 
 		memset(nulls, 0, sizeof(nulls));
@@ -3328,6 +3360,11 @@ pg_stat_get_wal_senders(PG_FUNCTION_ARGS)
 					CStringGetTextDatum("sync") : CStringGetTextDatum("quorum");
 			else
 				values[10] = CStringGetTextDatum("potential");
+
+			if (replyTime == 0)
+				nulls[11] = true;
+			else
+				values[11] = TimestampTzGetDatum(replyTime);
 		}
 
 		tuplestore_putvalues(tupstore, tupdesc, values, nulls);
diff --git a/src/include/catalog/catversion.h b/src/include/catalog/catversion.h
index be72bddd17..eec843cf7e 100644
--- a/src/include/catalog/catversion.h
+++ b/src/include/catalog/catversion.h
@@ -53,6 +53,6 @@
  */
 
 /*							yyyymmddN */
-#define CATALOG_VERSION_NO	201811201
+#define CATALOG_VERSION_NO	201812041
 
 #endif
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index 034a41eb55..f79fcfe029 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5023,9 +5023,9 @@
   proname => 'pg_stat_get_wal_senders', prorows => '10', proisstrict => 'f',
   proretset => 't', provolatile => 's', proparallel => 'r',
   prorettype => 'record', proargtypes => '',
-  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text}',
-  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o}',
-  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state}',
+  proallargtypes => '{int4,text,pg_lsn,pg_lsn,pg_lsn,pg_lsn,interval,interval,interval,int4,text,timestamptz}',
+  proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}',
+  proargnames => '{pid,state,sent_lsn,write_lsn,flush_lsn,replay_lsn,write_lag,flush_lag,replay_lag,sync_priority,sync_state,reply_time}',
   prosrc => 'pg_stat_get_wal_senders' },
 { oid => '3317', descr => 'statistics: information about WAL receiver',
   proname => 'pg_stat_get_wal_receiver', proisstrict => 'f', provolatile => 's',
diff --git a/src/include/replication/walsender_private.h b/src/include/replication/walsender_private.h
index 4b90477936..7aba153ff6 100644
--- a/src/include/replication/walsender_private.h
+++ b/src/include/replication/walsender_private.h
@@ -75,6 +75,11 @@ typedef struct WalSnd
 	 * SyncRepLock.
 	 */
 	int			sync_standby_priority;
+
+	/*
+	 * Timestamp of the last message received from standby.
+	 */
+	TimestampTz	replyTime;
 } WalSnd;
 
 extern WalSnd *MyWalSnd;
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 735dd37acf..b68b8d273f 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1861,9 +1861,10 @@ pg_stat_replication| SELECT s.pid,
     w.flush_lag,
     w.replay_lag,
     w.sync_priority,
-    w.sync_state
+    w.sync_state,
+    w.reply_time
    FROM ((pg_stat_get_activity(NULL::integer) s(datid, pid, usesysid, application_name, state, query, wait_event_type, wait_event, xact_start, query_start, backend_start, state_change, client_addr, client_hostname, client_port, backend_xid, backend_xmin, backend_type, ssl, sslversion, sslcipher, sslbits, sslcompression, sslclientdn)
-     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state) ON ((s.pid = w.pid)))
+     JOIN pg_stat_get_wal_senders() w(pid, state, sent_lsn, write_lsn, flush_lsn, replay_lsn, write_lag, flush_lag, replay_lag, sync_priority, sync_state, reply_time) ON ((s.pid = w.pid)))
      LEFT JOIN pg_authid u ON ((s.usesysid = u.oid)));
 pg_stat_ssl| SELECT s.pid,
     s.ssl,
#18Michael Paquier
michael@paquier.xyz
In reply to: Michael Paquier (#17)
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

#19myungkyu.lim
myungkyu.lim@samsung.com
In reply to: Michael Paquier (#18)
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?)

#20Michael Paquier
michael@paquier.xyz
In reply to: myungkyu.lim (#19)
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

#21myungkyu.lim
myungkyu.lim@samsung.com
In reply to: Michael Paquier (#20)
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

#22Michael Paquier
michael@paquier.xyz
In reply to: myungkyu.lim (#21)
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