On Tue, 2020-12-01 at 17:32 +0100, Magnus Hagander wrote: > > I have changed "connections" to "sessions" and renamed the new > > column "connections" to "session_count". > > > > I think that most people will understand a session as started after a > > successful > > connection. > > Yeah, I agree, and as long as it's consistent we don't need more explanations > than that. > > Further int he views, it's a bit strange to have session_count and > aborted_session, but I'm not > sure what to suggest. "aborted_session_count" seems too long. Maybe just > "sessions" instead > of "session_count" -- no other counters actually have the "_count" suffix.
"sessions" is fine, I think; I changed the name. > > > I wonder if there would also be a way to count "sessions that crashed" as > > > well. > > > That is,the ones that failed in a way that caused the postmaster to > > > restart the system. > > > > Sure, a crash count would be useful. I don't know if it is easy for the > > stats collector > > to tell the difference between a start after a backend crash and - say - > > starting from > > a base backup. > > > > I think that that would be material for another patch, and I don't think it > > should go > > to "pg_stat_database", because a) it might be hard to tell to which > > database the crashed > > backend was attached, b) it might be a background process that doesn't > > belong to a database > > and c) if the crash were caused by - say - corruption in a shared catalog, > > it would be > > misleading > > I'm not sure it is outside the scope of this patch, because I think it might > be easier to > do than I (and I think you) first thought. We don't need to track which > database crashed -- > if we track all *other* ways a database exits, then crashes are all that > remains. > > So in fact, we *almost* have all the data we need already. We have the number > of sessions > started. We have the number of sessions "aborted". if we also had the number > of sessions > that were closed normally, then whatever is "left" would be the number of > sessions crashed. > And we do already, in your patch, send the message in the case of both > aborted and > non-aborted sessions. So we just need to keep track of both in the statsfile > (which we don't now), and we'd more or less have it, wouldn't we? There is one problem with that: the statistics collector is not guaranteed to get all messages, right? If a disconnection statistics UDP datagram doesn't reach the statistics collector, that connection would end up being reported as crashed. That would alarm people unnecessarily and make the crash statistics misleading. > However, some thinking around that also leads me to another question which is > very much > in scope for this patch regardless, which is what about shutdown and admin > termination. > Right now, when you do a "pg_ctl stop" on the database, all sessions count > as aborted. > Same thing for a pg_terminate_backend(). I wonder if this is also a case > that would be > useful to track as a separate thing? One could argue that the docs in your > patch say > aborted means "terminated by something else than a regular client > disconnection". > But that's true for a "shutdown", but not for a crash, so whichever way we go > with crashes > it's slightly incorrect. > But thinking from a usability perspective, wouldn't what we want more be > something > like <closed by correct disconnect>, <closed by abnormal disconnect>, > <closed by admin>, > <crash>? > > What do you think of adapting it to that? > > Basically, that would change pgStatSessionDisconnectedNormally into instead > being an > enum of reasons, which could be normal disconnect, abnormal disconnect and > admin. > And we'd track all those three as separate numbers in the stats file, > meaning we could > then calculate the crash by subtracting all three from the total number of > sessions? I think at least "closed by admin" might be interesting; I'll have a look. I don't think we have to specifically count "closed by normal disconnect", because that should be the rule and could be more or less deduced from the other numbers (with the uncertainty mentioned above). > (Let me know if you think the idea could work and would prefer it if I worked > up a > complete suggestion based on it rather than just spitting ideas) Thanks for the offer, and I'll get back to it if I get stuck. But I'm ready to do the grunt work, so that you can spend your precious committer cycles elsewhere :^) I'll have a go at "closed by admin", meanwhile here is patch v7 with the renaming "session_count -> sessions". Yours, Laurenz Albe
From 8feed416f91a5de9011616c1545156b9c8f28943 Mon Sep 17 00:00:00 2001 From: Laurenz Albe <laurenz.a...@cybertec.at> Date: Fri, 20 Nov 2020 15:11:57 +0100 Subject: [PATCH] Add session statistics to pg_stat_database If "track_counts" is active, track the following per database: - total number of connections - number of sessions that ended other than with a client disconnect - total time spent in database sessions - total time spent executing queries - total idle in transaction time This is useful to check if connection pooling is working. It also helps to estimate the size of the connection pool required to keep the database busy, which depends on the percentage of the transaction time that is spent idling. Discussion: https://postgr.es/m/b07e1f9953701b90c66ed368656f2aef40cac4fb.ca...@cybertec.at Reviewed-By: Soumyadeep Chakraborty, Justin Pryzby, Masahiro Ikeda, Magnus Hagander (This requires a catversion bump, as well as an update to PGSTAT_FILE_FORMAT_ID) --- doc/src/sgml/monitoring.sgml | 49 +++++++++++ src/backend/catalog/system_views.sql | 5 ++ src/backend/postmaster/pgstat.c | 117 ++++++++++++++++++++++++++- src/backend/tcop/postgres.c | 5 ++ src/backend/utils/adt/pgstatfuncs.c | 68 ++++++++++++++++ src/include/catalog/pg_proc.dat | 20 +++++ src/include/pgstat.h | 27 +++++++ src/test/regress/expected/rules.out | 5 ++ 8 files changed, 292 insertions(+), 4 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 98e1995453..21742ce81e 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3704,6 +3704,55 @@ SELECT pid, wait_event_type, wait_event FROM pg_stat_activity WHERE wait_event i </para></entry> </row> + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>session_time</structfield> <type>double precision</type> + </para> + <para> + Time spent by database sessions in this database, in milliseconds + (note that statistics are only updated when the state of a session + changes, so if sessions have been idle for a long time, this idle time + won't be included) + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>active_time</structfield> <type>double precision</type> + </para> + <para> + Time spent executing SQL statements in this database, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>idle_in_transaction_time</structfield> <type>double precision</type> + </para> + <para> + Time spent idling while in a transaction in this database, in milliseconds + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>sessions</structfield> <type>bigint</type> + </para> + <para> + Total number of sessions established to this database + </para></entry> + </row> + + <row> + <entry role="catalog_table_entry"><para role="column_definition"> + <structfield>aborted_sessions</structfield> <type>bigint</type> + </para> + <para> + Number of database sessions to this database that were terminated + by something else than a regular client disconnection + </para></entry> + </row> + <row> <entry role="catalog_table_entry"><para role="column_definition"> <structfield>stats_reset</structfield> <type>timestamp with time zone</type> diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index 2e4aa1c4b6..e941b9e0f6 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -924,6 +924,11 @@ CREATE VIEW pg_stat_database AS pg_stat_get_db_checksum_last_failure(D.oid) AS checksum_last_failure, pg_stat_get_db_blk_read_time(D.oid) AS blk_read_time, pg_stat_get_db_blk_write_time(D.oid) AS blk_write_time, + pg_stat_get_db_session_time(D.oid) AS session_time, + pg_stat_get_db_active_time(D.oid) AS active_time, + pg_stat_get_db_idle_in_transaction_time(D.oid) AS idle_in_transaction_time, + pg_stat_get_db_sessions(D.oid) AS sessions, + pg_stat_get_db_aborted_sessions(D.oid) AS aborted_sessions, pg_stat_get_db_stat_reset_time(D.oid) AS stats_reset FROM ( SELECT 0 AS oid, NULL::name AS datname diff --git a/src/backend/postmaster/pgstat.c b/src/backend/postmaster/pgstat.c index e76e627c6b..d5be1cae4b 100644 --- a/src/backend/postmaster/pgstat.c +++ b/src/backend/postmaster/pgstat.c @@ -249,6 +249,9 @@ static int pgStatXactCommit = 0; static int pgStatXactRollback = 0; PgStat_Counter pgStatBlockReadTime = 0; PgStat_Counter pgStatBlockWriteTime = 0; +static PgStat_Counter pgStatActiveTime = 0; +static PgStat_Counter pgStatTransactionIdleTime = 0; +bool pgStatSessionDisconnectedNormally = false; /* Record that's written to 2PC state file when pgstat state is persisted */ typedef struct TwoPhasePgStatRecord @@ -334,6 +337,7 @@ static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg); static void pgstat_send_funcstats(void); static void pgstat_send_slru(void); static HTAB *pgstat_collect_oids(Oid catalogid, AttrNumber anum_oid); +static void pgstat_send_connstats(bool disconnect, TimestampTz last_report); static PgStat_TableStatus *get_tabstat_entry(Oid rel_id, bool isshared); @@ -369,6 +373,7 @@ static void pgstat_recv_funcpurge(PgStat_MsgFuncpurge *msg, int len); static void pgstat_recv_recoveryconflict(PgStat_MsgRecoveryConflict *msg, int len); static void pgstat_recv_deadlock(PgStat_MsgDeadlock *msg, int len); static void pgstat_recv_checksum_failure(PgStat_MsgChecksumFailure *msg, int len); +static void pgstat_recv_connstat(PgStat_MsgConn *msg, int len); static void pgstat_recv_replslot(PgStat_MsgReplSlot *msg, int len); static void pgstat_recv_tempfile(PgStat_MsgTempFile *msg, int len); @@ -844,10 +849,14 @@ allow_immediate_pgstat_restart(void) * per-table and function usage statistics to the collector. Note that this * is called only when not within a transaction, so it is fair to use * transaction stop time as an approximation of current time. + * + * "disconnect" is "true" only for the last call before the backend + * exits. This makes sure that no data are lost and that interrupted + * sessions are reported correctly. * ---------- */ void -pgstat_report_stat(bool force) +pgstat_report_stat(bool disconnect) { /* we assume this inits to all zeroes: */ static const PgStat_TableCounts all_zeroes; @@ -862,17 +871,22 @@ pgstat_report_stat(bool force) /* Don't expend a clock check if nothing to do */ if ((pgStatTabList == NULL || pgStatTabList->tsa_used == 0) && pgStatXactCommit == 0 && pgStatXactRollback == 0 && - !have_function_stats) + !have_function_stats && !disconnect) return; /* * Don't send a message unless it's been at least PGSTAT_STAT_INTERVAL - * msec since we last sent one, or the caller wants to force stats out. + * msec since we last sent one, or the backend is about to exit. */ now = GetCurrentTransactionStopTimestamp(); - if (!force && + if (!disconnect && !TimestampDifferenceExceeds(last_report, now, PGSTAT_STAT_INTERVAL)) return; + + /* for backends, send connection statistics */ + if (MyBackendType == B_BACKEND) + pgstat_send_connstats(disconnect, last_report); + last_report = now; /* @@ -1341,6 +1355,48 @@ pgstat_drop_relation(Oid relid) #endif /* NOT_USED */ +/* ---------- + * pgstat_send_connstats() - + * + * Tell the collector about session statistics. + * The parameter "disconnect" will be true when the backend exits. + * "last_report" is the last time we were called (0 if never). + * ---------- + */ +static void +pgstat_send_connstats(bool disconnect, TimestampTz last_report) +{ + PgStat_MsgConn msg; + long secs; + int usecs; + + if (pgStatSock == PGINVALID_SOCKET || !pgstat_track_counts) + return; + + pgstat_setheader(&msg.m_hdr, PGSTAT_MTYPE_CONNECTION); + msg.m_databaseid = MyDatabaseId; + + /* session time since the last report */ + TimestampDifference(((last_report == 0) ? MyStartTimestamp : last_report), + GetCurrentTimestamp(), + &secs, &usecs); + msg.m_session_time = secs * 1000000 + usecs; + + msg.m_aborted = (!disconnect || pgStatSessionDisconnectedNormally) ? 0 : 1; + + msg.m_active_time = pgStatActiveTime; + pgStatActiveTime = 0; + + msg.m_idle_in_xact_time = pgStatTransactionIdleTime; + pgStatTransactionIdleTime = 0; + + /* report a new session only the first time */ + msg.m_count = (last_report == 0) ? 1 : 0; + + pgstat_send(&msg, sizeof(PgStat_MsgConn)); +} + + /* ---------- * pgstat_reset_counters() - * @@ -3327,6 +3383,30 @@ pgstat_report_activity(BackendState state, const char *cmd_str) } current_timestamp = GetCurrentTimestamp(); + /* + * If the state has changed from "active" or "idle in transaction", + * calculate the duration. + */ + 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) + { + long secs; + int usecs; + + TimestampDifference(beentry->st_state_start_timestamp, + current_timestamp, + &secs, &usecs); + + if (beentry->st_state == STATE_RUNNING || + beentry->st_state == STATE_FASTPATH) + pgStatActiveTime += secs * 1000000 + usecs; + else + pgStatTransactionIdleTime += secs * 1000000 + usecs; + } + /* * Now update the status entry */ @@ -4879,6 +4959,10 @@ PgstatCollectorMain(int argc, char *argv[]) pgstat_recv_replslot(&msg.msg_replslot, len); break; + case PGSTAT_MTYPE_CONNECTION: + pgstat_recv_connstat(&msg.msg_conn, len); + break; + default: break; } @@ -4953,6 +5037,11 @@ reset_dbentry_counters(PgStat_StatDBEntry *dbentry) dbentry->last_checksum_failure = 0; dbentry->n_block_read_time = 0; dbentry->n_block_write_time = 0; + dbentry->n_sessions = 0; + dbentry->n_session_time = 0; + dbentry->n_active_time = 0; + dbentry->n_idle_in_xact_time = 0; + dbentry->n_aborted = 0; dbentry->stat_reset_timestamp = GetCurrentTimestamp(); dbentry->stats_timestamp = 0; @@ -6903,6 +6992,26 @@ pgstat_recv_replslot(PgStat_MsgReplSlot *msg, int len) } } +/* ---------- + * pgstat_recv_connstat() - + * + * Process connection information. + * ---------- + */ +static void +pgstat_recv_connstat(PgStat_MsgConn *msg, int len) +{ + PgStat_StatDBEntry *dbentry; + + dbentry = pgstat_get_db_entry(msg->m_databaseid, true); + + dbentry->n_sessions += msg->m_count; + dbentry->n_session_time += msg->m_session_time; + dbentry->n_active_time += msg->m_active_time; + dbentry->n_idle_in_xact_time += msg->m_idle_in_xact_time; + dbentry->n_aborted += msg->m_aborted; +} + /* ---------- * pgstat_recv_tempfile() - * diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 7c5f7c775b..514ee532db 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -4494,6 +4494,11 @@ PostgresMain(int argc, char *argv[], * perform normal shutdown. */ case 'X': + /* report as normal client disconnection */ + pgStatSessionDisconnectedNormally = true; + + /* FALLTHROUGH */ + case EOF: /* diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index a210fc93b4..aaf2d77515 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -1629,6 +1629,74 @@ pg_stat_get_db_blk_write_time(PG_FUNCTION_ARGS) PG_RETURN_FLOAT8(result); } +Datum +pg_stat_get_db_session_time(PG_FUNCTION_ARGS) +{ + Oid dbid = PG_GETARG_OID(0); + double result = 0.0; + PgStat_StatDBEntry *dbentry; + + /* convert counter from microsec to millisec for display */ + if ((dbentry = pgstat_fetch_stat_dbentry(dbid)) != NULL) + result = ((double) dbentry->n_session_time) / 1000.0; + + PG_RETURN_FLOAT8(result); +} + +Datum +pg_stat_get_db_active_time(PG_FUNCTION_ARGS) +{ + Oid dbid = PG_GETARG_OID(0); + double result = 0.0; + PgStat_StatDBEntry *dbentry; + + /* convert counter from microsec to millisec for display */ + if ((dbentry = pgstat_fetch_stat_dbentry(dbid)) != NULL) + result = ((double) dbentry->n_active_time) / 1000.0; + + PG_RETURN_FLOAT8(result); +} + +Datum +pg_stat_get_db_idle_in_transaction_time(PG_FUNCTION_ARGS) +{ + Oid dbid = PG_GETARG_OID(0); + double result = 0.0; + PgStat_StatDBEntry *dbentry; + + /* convert counter from microsec to millisec for display */ + if ((dbentry = pgstat_fetch_stat_dbentry(dbid)) != NULL) + result = ((double) dbentry->n_idle_in_xact_time) / 1000.0; + + PG_RETURN_FLOAT8(result); +} + +Datum +pg_stat_get_db_sessions(PG_FUNCTION_ARGS) +{ + Oid dbid = PG_GETARG_OID(0); + int64 result = 0.0; + PgStat_StatDBEntry *dbentry; + + if ((dbentry = pgstat_fetch_stat_dbentry(dbid)) != NULL) + result = (int64) (dbentry->n_sessions); + + PG_RETURN_INT64(result); +} + +Datum +pg_stat_get_db_aborted_sessions(PG_FUNCTION_ARGS) +{ + Oid dbid = PG_GETARG_OID(0); + int64 result = 0.0; + PgStat_StatDBEntry *dbentry; + + if ((dbentry = pgstat_fetch_stat_dbentry(dbid)) != NULL) + result = (int64) (dbentry->n_aborted); + + PG_RETURN_INT64(result); +} + Datum pg_stat_get_bgwriter_timed_checkpoints(PG_FUNCTION_ARGS) { diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 33dacfd340..9adba05701 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5441,6 +5441,26 @@ proname => 'pg_stat_get_db_blk_write_time', provolatile => 's', proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', prosrc => 'pg_stat_get_db_blk_write_time' }, +{ oid => '9575', descr => 'statistics: session time, in seconds', + proname => 'pg_stat_get_db_session_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_session_time' }, +{ oid => '9576', descr => 'statistics: session active time, in seconds', + proname => 'pg_stat_get_db_active_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_active_time' }, +{ oid => '9577', descr => 'statistics: session idle in transaction time, in seconds', + proname => 'pg_stat_get_db_idle_in_transaction_time', provolatile => 's', + proparallel => 'r', prorettype => 'float8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_idle_in_transaction_time' }, +{ oid => '9578', descr => 'statistics: total number of sessions', + proname => 'pg_stat_get_db_sessions', provolatile => 's', + proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_sessions' }, +{ oid => '9579', descr => 'statistics: number of aborted sessions', + proname => 'pg_stat_get_db_aborted_sessions', provolatile => 's', + proparallel => 'r', prorettype => 'int8', proargtypes => 'oid', + prosrc => 'pg_stat_get_db_aborted_sessions' }, { oid => '3195', descr => 'statistics: information about WAL archiver', proname => 'pg_stat_get_archiver', proisstrict => 'f', provolatile => 's', proparallel => 'r', prorettype => 'record', proargtypes => '', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 257e515bfe..5f1641632c 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -71,6 +71,7 @@ typedef enum StatMsgType PGSTAT_MTYPE_DEADLOCK, PGSTAT_MTYPE_CHECKSUMFAILURE, PGSTAT_MTYPE_REPLSLOT, + PGSTAT_MTYPE_CONNECTION, } StatMsgType; /* ---------- @@ -619,6 +620,21 @@ typedef struct PgStat_MsgChecksumFailure TimestampTz m_failure_time; } PgStat_MsgChecksumFailure; +/* ---------- + * PgStat_MsgConn Sent by pgstat_connection to update connection statistics. + * ---------- + */ +typedef struct PgStat_MsgConn +{ + PgStat_MsgHdr m_hdr; + Oid m_databaseid; + PgStat_Counter m_count; + PgStat_Counter m_session_time; + PgStat_Counter m_active_time; + PgStat_Counter m_idle_in_xact_time; + PgStat_Counter m_aborted; +} PgStat_MsgConn; + /* ---------- * PgStat_Msg Union over all possible messages. @@ -651,6 +667,7 @@ typedef union PgStat_Msg PgStat_MsgTempFile msg_tempfile; PgStat_MsgChecksumFailure msg_checksumfailure; PgStat_MsgReplSlot msg_replslot; + PgStat_MsgConn msg_conn; } PgStat_Msg; @@ -693,6 +710,11 @@ typedef struct PgStat_StatDBEntry TimestampTz last_checksum_failure; PgStat_Counter n_block_read_time; /* times in microseconds */ PgStat_Counter n_block_write_time; + PgStat_Counter n_sessions; + PgStat_Counter n_session_time; + PgStat_Counter n_active_time; + PgStat_Counter n_idle_in_xact_time; + PgStat_Counter n_aborted; TimestampTz stat_reset_timestamp; TimestampTz stats_timestamp; /* time of db stats file update */ @@ -1347,6 +1369,11 @@ extern PgStat_MsgWal WalStats; extern PgStat_Counter pgStatBlockReadTime; extern PgStat_Counter pgStatBlockWriteTime; +/* + * Updated in PostgresMain upon disconnect. + */ +extern bool pgStatSessionDisconnectedNormally; + /* ---------- * Functions called from postmaster * ---------- diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index 097ff5d111..39d034ccab 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -1848,6 +1848,11 @@ pg_stat_database| SELECT d.oid AS datid, pg_stat_get_db_checksum_last_failure(d.oid) AS checksum_last_failure, pg_stat_get_db_blk_read_time(d.oid) AS blk_read_time, pg_stat_get_db_blk_write_time(d.oid) AS blk_write_time, + pg_stat_get_db_session_time(d.oid) AS session_time, + pg_stat_get_db_active_time(d.oid) AS active_time, + pg_stat_get_db_idle_in_transaction_time(d.oid) AS idle_in_transaction_time, + pg_stat_get_db_sessions(d.oid) AS sessions, + pg_stat_get_db_aborted_sessions(d.oid) AS aborted_sessions, pg_stat_get_db_stat_reset_time(d.oid) AS stats_reset FROM ( SELECT 0 AS oid, NULL::name AS datname -- 2.26.2
