Add connection active, idle time to pg_stat_activity

On Fri, 22 Oct 2021 at 10:22, Rafia Sabih <rafia.pghackers@gmail.com> wrote:

Hello there hackers,

We at Zalando have faced some issues around long running idle
transactions and were thinking about increasing the visibility of
pg_stat_* views to capture them easily. What I found is that currently
in pg_stat_activity there is a lot of good information about the
current state of the process, but it is lacking the cumulative
information on how much time the connection spent being idle, idle in
transaction or active, we would like to see cumulative values for each
of these per connection. I believe it would be helpful for us and more
people out there if we could have total connection active and idle
time displayed in pg_stat_activity.

To provide this information I was digging into how the statistics
collector is working and found out there is already information like
total time that a connection is active as well as idle computed in
pgstat_report_activity[1]. Ideally, this would be the values we would
like to see per process in pg_stat_activity.

Curious to know your thoughts on this.

[1]https://github.com/postgres/postgres/blob/cd3f429d9565b2e5caf0980ea7c707e37bc3b317/src/backend/utils/activity/backend_status.c#L593

--
Regards,
Rafia Sabih

Please find the attached patch for the idea of our intentions.
It basically adds three attributes for idle, idle_in_transaction, and
active time respectively.
Please let me know your views on this and I shall add this to the
upcoming commitfest for better tracking.

--
Regards,
Rafia Sabih

On Tue, Oct 26, 2021 at 5:17 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

To provide this information I was digging into how the statistics
collector is working and found out there is already information like
total time that a connection is active as well as idle computed in
pgstat_report_activity[1]. Ideally, this would be the values we would
like to see per process in pg_stat_activity.

Curious to know your thoughts on this.

+1 for the idea

Please find the attached patch for the idea of our intentions.
It basically adds three attributes for idle, idle_in_transaction, and
active time respectively.
Please let me know your views on this and I shall add this to the
upcoming commitfest for better tracking.

About the patch, IIUC earlier all the idle time was accumulated in the
"pgStatTransactionIdleTime" counter, now with your patch you have
introduced one more counter which specifically tracks the
STATE_IDLEINTRANSACTION state. But my concern is that the
STATE_IDLEINTRANSACTION_ABORTED is still computed under STATE_IDLE and
that looks odd to me. Either STATE_IDLEINTRANSACTION_ABORTED should
be accumulated in the "pgStatTransactionIdleInTxnTime" counter or
there should be a separate counter for that. But after your patch we
can not accumulate this in the "pgStatTransactionIdleTime" counter.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Tue, 2 Nov 2021 at 09:00, Dilip Kumar <dilipbalaut@gmail.com> wrote:

On Tue, Oct 26, 2021 at 5:17 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

To provide this information I was digging into how the statistics
collector is working and found out there is already information like
total time that a connection is active as well as idle computed in
pgstat_report_activity[1]. Ideally, this would be the values we would
like to see per process in pg_stat_activity.

Curious to know your thoughts on this.

+1 for the idea

Thanks!

Please find the attached patch for the idea of our intentions.
It basically adds three attributes for idle, idle_in_transaction, and
active time respectively.
Please let me know your views on this and I shall add this to the
upcoming commitfest for better tracking.

About the patch, IIUC earlier all the idle time was accumulated in the
"pgStatTransactionIdleTime" counter, now with your patch you have
introduced one more counter which specifically tracks the
STATE_IDLEINTRANSACTION state. But my concern is that the
STATE_IDLEINTRANSACTION_ABORTED is still computed under STATE_IDLE and
that looks odd to me. Either STATE_IDLEINTRANSACTION_ABORTED should
be accumulated in the "pgStatTransactionIdleInTxnTime" counter or
there should be a separate counter for that. But after your patch we
can not accumulate this in the "pgStatTransactionIdleTime" counter.

As per your comments I have added it in pgStatTransactionIdleInTxnTime.
Please let me know if there are any further comments.

--
Regards,
Rafia Sabih

On Tue, Nov 9, 2021 at 8:28 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

On Tue, 2 Nov 2021 at 09:00, Dilip Kumar <dilipbalaut@gmail.com> wrote:

About the patch, IIUC earlier all the idle time was accumulated in the
"pgStatTransactionIdleTime" counter, now with your patch you have
introduced one more counter which specifically tracks the
STATE_IDLEINTRANSACTION state. But my concern is that the
STATE_IDLEINTRANSACTION_ABORTED is still computed under STATE_IDLE and
that looks odd to me. Either STATE_IDLEINTRANSACTION_ABORTED should
be accumulated in the "pgStatTransactionIdleInTxnTime" counter or
there should be a separate counter for that. But after your patch we
can not accumulate this in the "pgStatTransactionIdleTime" counter.

As per your comments I have added it in pgStatTransactionIdleInTxnTime.
Please let me know if there are any further comments.

I have a few comments,

             nulls[29] = true;
+            values[30] = true;
+            values[31] = true;
+            values[32] = true;

This looks wrong, this should be nulls[] = true not values[]=true.

if ((beentry->st_state == STATE_RUNNING ||
beentry->st_state == STATE_FASTPATH ||
beentry->st_state == STATE_IDLEINTRANSACTION ||
beentry->st_state == STATE_IDLEINTRANSACTION_ABORTED) &&
state != beentry->st_state)
{
if (beentry->st_state == STATE_RUNNING ||
beentry->st_state == STATE_FASTPATH)
{
pgstat_count_conn_active_time((PgStat_Counter) secs * 1000000 + usecs);
beentry->st_active_time = pgStatActiveTime;
}
else if (beentry->st_state == STATE_IDLEINTRANSACTION ||
beentry->st_state == STATE_IDLEINTRANSACTION_ABORTED)
{
pgstat_count_conn_txn_idle_in_txn_time((PgStat_Counter) secs *
1000000 + usecs);
beentry->st_idle_in_transaction_time = pgStatTransactionIdleInTxnTime;
}
else
{
pgstat_count_conn_txn_idle_time((PgStat_Counter) secs * 1000000 + usecs);
beentry->st_idle_time = pgStatTransactionIdleTime;
}

It seems that in beentry->st_idle_time, you want to compute the
STATE_IDLE, but that state is not handled in the outer "if", that
means whenever it comes out of the
STATE_IDLE, it will not enter inside this if check. You can run and
test, I am sure that with this patch the "idle_time" will always
remain 0.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Wed, 10 Nov 2021 at 09:05, Dilip Kumar <dilipbalaut@gmail.com> wrote:

On Tue, Nov 9, 2021 at 8:28 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

On Tue, 2 Nov 2021 at 09:00, Dilip Kumar <dilipbalaut@gmail.com> wrote:

About the patch, IIUC earlier all the idle time was accumulated in the
"pgStatTransactionIdleTime" counter, now with your patch you have
introduced one more counter which specifically tracks the
STATE_IDLEINTRANSACTION state. But my concern is that the
STATE_IDLEINTRANSACTION_ABORTED is still computed under STATE_IDLE and
that looks odd to me. Either STATE_IDLEINTRANSACTION_ABORTED should
be accumulated in the "pgStatTransactionIdleInTxnTime" counter or
there should be a separate counter for that. But after your patch we
can not accumulate this in the "pgStatTransactionIdleTime" counter.

As per your comments I have added it in pgStatTransactionIdleInTxnTime.
Please let me know if there are any further comments.

I have a few comments,

nulls[29] = true;
+            values[30] = true;
+            values[31] = true;
+            values[32] = true;

This looks wrong, this should be nulls[] = true not values[]=true.

if ((beentry->st_state == STATE_RUNNING ||
beentry->st_state == STATE_FASTPATH ||
beentry->st_state == STATE_IDLEINTRANSACTION ||
beentry->st_state == STATE_IDLEINTRANSACTION_ABORTED) &&
state != beentry->st_state)
{
if (beentry->st_state == STATE_RUNNING ||
beentry->st_state == STATE_FASTPATH)
{
pgstat_count_conn_active_time((PgStat_Counter) secs * 1000000 + usecs);
beentry->st_active_time = pgStatActiveTime;
}
else if (beentry->st_state == STATE_IDLEINTRANSACTION ||
beentry->st_state == STATE_IDLEINTRANSACTION_ABORTED)
{
pgstat_count_conn_txn_idle_in_txn_time((PgStat_Counter) secs *
1000000 + usecs);
beentry->st_idle_in_transaction_time = pgStatTransactionIdleInTxnTime;
}
else
{
pgstat_count_conn_txn_idle_time((PgStat_Counter) secs * 1000000 + usecs);
beentry->st_idle_time = pgStatTransactionIdleTime;
}

It seems that in beentry->st_idle_time, you want to compute the
STATE_IDLE, but that state is not handled in the outer "if", that
means whenever it comes out of the
STATE_IDLE, it will not enter inside this if check. You can run and
test, I am sure that with this patch the "idle_time" will always
remain 0.

Thank you Dilip for your time on this.
And yes you are right in both your observations.
Please find the attached patch for the updated version.

--
Regards,
Rafia Sabih

On Wed, Nov 10, 2021 at 1:47 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

It seems that in beentry->st_idle_time, you want to compute the
STATE_IDLE, but that state is not handled in the outer "if", that
means whenever it comes out of the
STATE_IDLE, it will not enter inside this if check. You can run and
test, I am sure that with this patch the "idle_time" will always
remain 0.

Thank you Dilip for your time on this.
And yes you are right in both your observations.
Please find the attached patch for the updated version.

Looks fine now except these variable names,

PgStat_Counter pgStatTransactionIdleTime = 0;
+PgStat_Counter pgStatTransactionIdleInTxnTime = 0;

Now, pgStatTransactionIdleTime is collecting just the Idle time so
pgStatTransactionIdleTime should be renamed to "pgStatIdleTime" and
pgStatTransactionIdleInTxnTime should be renamed to
"pgStatTransactionIdleTime"

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Mon, 15 Nov 2021 at 10:24, Dilip Kumar <dilipbalaut@gmail.com> wrote:

On Wed, Nov 10, 2021 at 1:47 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

It seems that in beentry->st_idle_time, you want to compute the
STATE_IDLE, but that state is not handled in the outer "if", that
means whenever it comes out of the
STATE_IDLE, it will not enter inside this if check. You can run and
test, I am sure that with this patch the "idle_time" will always
remain 0.

Thank you Dilip for your time on this.
And yes you are right in both your observations.
Please find the attached patch for the updated version.

Looks fine now except these variable names,

PgStat_Counter pgStatTransactionIdleTime = 0;
+PgStat_Counter pgStatTransactionIdleInTxnTime = 0;

Now, pgStatTransactionIdleTime is collecting just the Idle time so
pgStatTransactionIdleTime should be renamed to "pgStatIdleTime" and
pgStatTransactionIdleInTxnTime should be renamed to
"pgStatTransactionIdleTime"

Good point!
Done.

--
Regards,
Rafia Sabih

On Mon, Nov 15, 2021 at 4:46 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

On Mon, 15 Nov 2021 at 10:24, Dilip Kumar <dilipbalaut@gmail.com> wrote:

On Wed, Nov 10, 2021 at 1:47 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

It seems that in beentry->st_idle_time, you want to compute the
STATE_IDLE, but that state is not handled in the outer "if", that
means whenever it comes out of the
STATE_IDLE, it will not enter inside this if check. You can run and
test, I am sure that with this patch the "idle_time" will always
remain 0.

Thank you Dilip for your time on this.
And yes you are right in both your observations.
Please find the attached patch for the updated version.

Looks fine now except these variable names,

PgStat_Counter pgStatTransactionIdleTime = 0;
+PgStat_Counter pgStatTransactionIdleInTxnTime = 0;

Now, pgStatTransactionIdleTime is collecting just the Idle time so
pgStatTransactionIdleTime should be renamed to "pgStatIdleTime" and
pgStatTransactionIdleInTxnTime should be renamed to
"pgStatTransactionIdleTime"

Good point!
Done.

@@ -1018,7 +1019,7 @@ pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg,
TimestampTz now)
  pgLastSessionReportTime = now;
  tsmsg->m_session_time = (PgStat_Counter) secs * 1000000 + usecs;
  tsmsg->m_active_time = pgStatActiveTime;
- tsmsg->m_idle_in_xact_time = pgStatTransactionIdleTime;
+ tsmsg->m_idle_in_xact_time = pgStatIdleTime;

I think this change is wrong, basically, "tsmsg->m_idle_in_xact_time"
is used for counting the database level idle in transaction count, you
can check "pg_stat_get_db_idle_in_transaction_time" function for that.
So "pgStatTransactionIdleTime" is the variable counting the idle in
transaction time, pgStatIdleTime is just counting the idle time
outside the transaction so if we make this change we are changing the
meaning of tsmsg->m_idle_in_xact_time.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Mon, 15 Nov 2021 at 12:40, Dilip Kumar <dilipbalaut@gmail.com> wrote:

On Mon, Nov 15, 2021 at 4:46 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

On Mon, 15 Nov 2021 at 10:24, Dilip Kumar <dilipbalaut@gmail.com> wrote:

On Wed, Nov 10, 2021 at 1:47 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

It seems that in beentry->st_idle_time, you want to compute the
STATE_IDLE, but that state is not handled in the outer "if", that
means whenever it comes out of the
STATE_IDLE, it will not enter inside this if check. You can run and
test, I am sure that with this patch the "idle_time" will always
remain 0.

Thank you Dilip for your time on this.
And yes you are right in both your observations.
Please find the attached patch for the updated version.

Looks fine now except these variable names,

PgStat_Counter pgStatTransactionIdleTime = 0;
+PgStat_Counter pgStatTransactionIdleInTxnTime = 0;

Now, pgStatTransactionIdleTime is collecting just the Idle time so
pgStatTransactionIdleTime should be renamed to "pgStatIdleTime" and
pgStatTransactionIdleInTxnTime should be renamed to
"pgStatTransactionIdleTime"

Good point!
Done.

@@ -1018,7 +1019,7 @@ pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg,
TimestampTz now)
pgLastSessionReportTime = now;
tsmsg->m_session_time = (PgStat_Counter) secs * 1000000 + usecs;
tsmsg->m_active_time = pgStatActiveTime;
- tsmsg->m_idle_in_xact_time = pgStatTransactionIdleTime;
+ tsmsg->m_idle_in_xact_time = pgStatIdleTime;

I think this change is wrong, basically, "tsmsg->m_idle_in_xact_time"
is used for counting the database level idle in transaction count, you
can check "pg_stat_get_db_idle_in_transaction_time" function for that.
So "pgStatTransactionIdleTime" is the variable counting the idle in
transaction time, pgStatIdleTime is just counting the idle time
outside the transaction so if we make this change we are changing the
meaning of tsmsg->m_idle_in_xact_time.

Got it.
Updated

--
Regards,
Rafia Sabih

On Tue, Nov 16, 2021 at 5:06 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

I think this change is wrong, basically, "tsmsg->m_idle_in_xact_time"
is used for counting the database level idle in transaction count, you
can check "pg_stat_get_db_idle_in_transaction_time" function for that.
So "pgStatTransactionIdleTime" is the variable counting the idle in
transaction time, pgStatIdleTime is just counting the idle time
outside the transaction so if we make this change we are changing the
meaning of tsmsg->m_idle_in_xact_time.

Got it.
Updated

Okay, thanks, I will look into it one more time early next week and if
I see no issues then I will move it to RFC.

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Tue, Nov 16, 2021 at 5:06 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

Got it.
Updated

Thanks for the patch. +1 for adding the idle/idle_in_txn_time/active
time. I believe these are the total times a backend in its lifetime
accumulates. For instance, if a backend runs 100 txns, then these new
columns show the total time that the backend spent during these 100
txns, right?

Few comments on the patch:

1) Patch is missing a commit message. It is good to have a commit
message describing the high-level of the feature.
2) This patch needs to bump the catalog version, at the end of the
commit message, we usually keep a note "Bump the catalog version".
3) It looks like the documentation is missing [1]https://www.postgresql.org/docs/devel/monitoring-stats.html#MONITORING-PG-STAT-ACTIVITY-VIEW, for the new columns.
4) When will these backend variables be reset? Is it at the backend
startup? Or some other? If these variables are reset only at the
backend startup and do they keep growing during the entire life of the
backend process? If yes, what happens for a long running backend/user
session, don't they get overflowed?

+
+ int64 st_active_time;
+ int64 st_transaction_idle_time;
+ int64 st_idle_time;
 } PgBackendStatus;

5) Is there any way you can get them tested?
6) What will be entries of st_active_time, st_transaction_idle_time,
st_idle_time for non-backend processes, like bg writer, checkpointer,
parallel worker, bg worker, logical replication launcher, stats
collector, sys logger etc?

[1]: https://www.postgresql.org/docs/devel/monitoring-stats.html#MONITORING-PG-STAT-ACTIVITY-VIEW

Regards,
Bharath Rupireddy.

On Sat, Nov 27, 2021 at 8:00 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:

On Tue, Nov 16, 2021 at 5:06 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

Got it.
Updated

Thanks for the patch. +1 for adding the idle/idle_in_txn_time/active
time. I believe these are the total times a backend in its lifetime
accumulates. For instance, if a backend runs 100 txns, then these new
columns show the total time that the backend spent during these 100
txns, right?

Few comments on the patch:

1) Patch is missing a commit message. It is good to have a commit
message describing the high-level of the feature.
2) This patch needs to bump the catalog version, at the end of the
commit message, we usually keep a note "Bump the catalog version".
3) It looks like the documentation is missing [1], for the new columns.
4) When will these backend variables be reset? Is it at the backend
startup? Or some other? If these variables are reset only at the
backend startup and do they keep growing during the entire life of the
backend process? If yes, what happens for a long running backend/user
session, don't they get overflowed?

This is a 64-bit variable so I am not sure do we really need to worry
about overflow? I mean if we are storing microseconds then also this
will be able to last for ~300,000 years no?

--
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

On Fri, Oct 22, 2021 at 1:53 PM Rafia Sabih <rafia.pghackers@gmail.com> wrote:

To provide this information I was digging into how the statistics
collector is working and found out there is already information like
total time that a connection is active as well as idle computed in
pgstat_report_activity[1]. Ideally, this would be the values we would
like to see per process in pg_stat_activity.

It's definitely useful to know how much time a backend has spent for
query executions. Once you've this info, you can easily calculate the
idle time using this information: (now() - backend_start) -
active_time. But, I'm wondering why you need to distinguish between
idle and idle in transactions - what's the usage? Either the backend
is doing some work or it sits idle. Another useful information would
be when the last query execution was ended. From this information, you
can figure out whether a backend is idle for a long time since the
last execution and the execution time of the last query (query_end -
query_start).

You also need to update the documentation.

--
Thanks & Regards,
Kuntal Ghosh

Hi,

On Mon, Nov 29, 2021 at 11:04 PM Kuntal Ghosh
<kuntalghosh.2007@gmail.com> wrote:

You also need to update the documentation.

You also need to update rules.sql: https://cirrus-ci.com/task/6145265819189248

Hi,

On Wed, Jan 12, 2022 at 02:16:35PM +0800, Julien Rouhaud wrote:

On Mon, Nov 29, 2021 at 11:04 PM Kuntal Ghosh
<kuntalghosh.2007@gmail.com> wrote:

You also need to update the documentation.

You also need to update rules.sql: https://cirrus-ci.com/task/6145265819189248

There has been multiple comments in the last two months that weren't addressed
since, and also the patch doesn't pass the regression tests anymore.

Rafia, do you plan to send a new version soon? Without update in the next few
days this patch will be closed as Returned with Feedback, per the commitfest
rules.

Hello,

Without update in the next few
days this patch will be closed as Returned with Feedback,

Thank you for the reminder, Julien.

Per agreement with Rafia I have reworked the patch in the past days.
The new version 6 is now ready for review.

Regards,
Sergey Dudoladov

Hi,

On Thu, Jan 27, 2022 at 11:43:26AM +0100, Sergey Dudoladov wrote:

Per agreement with Rafia I have reworked the patch in the past days.
The new version 6 is now ready for review.

Great, thanks a lot Sergey!

The cfbot is happy with this new version:
https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/36/3405

Hi.

At Thu, 27 Jan 2022 20:36:56 +0800, Julien Rouhaud <rjuju123@gmail.com> wrote in

On Thu, Jan 27, 2022 at 11:43:26AM +0100, Sergey Dudoladov wrote:

Per agreement with Rafia I have reworked the patch in the past days.
The new version 6 is now ready for review.

Great, thanks a lot Sergey!

The cfbot is happy with this new version:
https://cirrus-ci.com/github/postgresql-cfbot/postgresql/commitfest/36/3405

I think we can easily add the duration of the current state to the two
in pg_stat_get_activity and it would offer better information.

 		if (beentry->st_state == STATE_RUNNING ||
 			beentry->st_state == STATE_FASTPATH)
-			pgstat_count_conn_active_time((PgStat_Counter) secs * 1000000 + usecs);
+		{
+			pgstat_count_conn_active_time((PgStat_Counter) usecs_diff);
+			beentry->st_total_active_time += usecs_diff;
+		}

The two lines operates exactly the same way on variables with slightly
different behavior. pgStatActiveTime is reported at transaction end
and reset at every tabstat reporting. st_total_active_time is reported
immediately and reset at session end. Since we do the latter, the
first can be omitted by remembering the last values for the local
variables at every reporting. This needs additional two exporting
function in pgstatfuncs like pgstat_get_my_queryid so others might
think differently.

The write operation to beentry needs to be enclosed by
PGSTAT_BEGIN/END_WRITE_ACTIVITY(). In that perspective, it would be
better to move that writes to the PGSTAT_WRITE_ACTIVITY section just
below.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

At Mon, 29 Nov 2021 20:34:14 +0530, Kuntal Ghosh <kuntalghosh.2007@gmail.com> wrote in

active_time. But, I'm wondering why you need to distinguish between
idle and idle in transactions - what's the usage? Either the backend
is doing some work or it sits idle. Another useful information would

I believe many people suffer from mysterious long idle in
transactions, which harm server performance many ways. In many cases
transactions with unexpectedly long idle time is an omen or a cause of
trouble.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center