Skip to content

Commit 7890a42

Browse files
anarazelanarazel
committed
Fix performance regression from session statistics.
Session statistics, as introduced by 960869d, had several shortcomings: - an additional GetCurrentTimestamp() call that also impaired the accuracy of the data collected This can be avoided by passing the current timestamp we already have in pgstat_report_stat(). - an additional statistics UDP packet sent every 500ms This is solved by adding the new statistics to PgStat_MsgTabstat. This is conceptually ugly, because session statistics are not table statistics. But the struct already contains data unrelated to tables, so there is not much damage done. Connection and disconnection are reported in separate messages, which reduces the number of additional messages to two messages per session and a slight increase in PgStat_MsgTabstat size (but the same number of table stats fit). - Session time computation could overflow on systems where long is 32 bit. Reported-By: Andres Freund <andres@anarazel.de> Author: Andres Freund <andres@anarazel.de> Author: Laurenz Albe <laurenz.albe@cybertec.at> Discussion: https://postgr.es/m/20210801205501.nyxzxoelqoo4x2qc%40alap3.anarazel.de Backpatch: 14-, where the feature was introduced.
1 parent 92a8d76 commit 7890a42

File tree

5 files changed

+158
-80
lines changed

5 files changed

+158
-80
lines changed

‎src/backend/postmaster/pgstat.c

Lines changed: 129 additions & 66 deletions
Original file line numberDiff line numberDiff line change
@@ -244,6 +244,7 @@ static int pgStatXactCommit = 0;
244244
static int pgStatXactRollback = 0;
245245
PgStat_Counter pgStatBlockReadTime = 0;
246246
PgStat_Counter pgStatBlockWriteTime = 0;
247+
static PgStat_Counter pgLastSessionReportTime = 0;
247248
PgStat_Counter pgStatActiveTime = 0;
248249
PgStat_Counter pgStatTransactionIdleTime = 0;
249250
SessionEndType pgStatSessionEndCause = DISCONNECT_NORMAL;
@@ -319,11 +320,12 @@ static bool pgstat_db_requested(Oid databaseid);
319320
static PgStat_StatReplSlotEntry *pgstat_get_replslot_entry(NameData name, bool create_it);
320321
static void pgstat_reset_replslot(PgStat_StatReplSlotEntry *slotstats, TimestampTz ts);
321322

322-
static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg);
323+
static void pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg, TimestampTz now);
323324
static void pgstat_send_funcstats(void);
324325
static void pgstat_send_slru(void);
325326
static HTAB *pgstat_collect_oids(Oid catalogid, AttrNumber anum_oid);
326-
static void pgstat_send_connstats(bool disconnect, TimestampTz last_report);
327+
static bool pgstat_should_report_connstat(void);
328+
static void pgstat_report_disconnect(Oid dboid);
327329

328330
static PgStat_TableStatus *get_tabstat_entry(Oid rel_id, bool isshared);
329331

@@ -353,7 +355,8 @@ static void pgstat_recv_funcpurge(PgStat_MsgFuncpurge *msg, int len);
353355
static void pgstat_recv_recoveryconflict(PgStat_MsgRecoveryConflict *msg, int len);
354356
static void pgstat_recv_deadlock(PgStat_MsgDeadlock *msg, int len);
355357
static void pgstat_recv_checksum_failure(PgStat_MsgChecksumFailure *msg, int len);
356-
static void pgstat_recv_connstat(PgStat_MsgConn *msg, int len);
358+
static void pgstat_recv_connect(PgStat_MsgConnect *msg, int len);
359+
static void pgstat_recv_disconnect(PgStat_MsgDisconnect *msg, int len);
357360
static void pgstat_recv_replslot(PgStat_MsgReplSlot *msg, int len);
358361
static void pgstat_recv_tempfile(PgStat_MsgTempFile *msg, int len);
359362

@@ -875,12 +878,11 @@ pgstat_report_stat(bool disconnect)
875878
!TimestampDifferenceExceeds(last_report, now, PGSTAT_STAT_INTERVAL))
876879
return;
877880

878-
/* for backends, send connection statistics */
879-
if (MyBackendType == B_BACKEND)
880-
pgstat_send_connstats(disconnect, last_report);
881-
882881
last_report = now;
883882

883+
if (disconnect)
884+
pgstat_report_disconnect(MyDatabaseId);
885+
884886
/*
885887
* Destroy pgStatTabHash before we start invalidating PgStat_TableEntry
886888
* entries it points to. (Should we fail partway through the loop below,
@@ -932,7 +934,7 @@ pgstat_report_stat(bool disconnect)
932934
sizeof(PgStat_TableCounts));
933935
if (++this_msg->m_nentries >= PGSTAT_NUM_TABENTRIES)
934936
{
935-
pgstat_send_tabstat(this_msg);
937+
pgstat_send_tabstat(this_msg, now);
936938
this_msg->m_nentries = 0;
937939
}
938940
}
@@ -944,13 +946,14 @@ pgstat_report_stat(bool disconnect)
944946

945947
/*
946948
* Send partial messages. Make sure that any pending xact commit/abort
947-
* gets counted, even if there are no table stats to send.
949+
* and connection stats get counted, even if there are no table stats to
950+
* send.
948951
*/
949952
if (regular_msg.m_nentries > 0 ||
950-
pgStatXactCommit > 0 || pgStatXactRollback > 0)
951-
pgstat_send_tabstat(&regular_msg);
953+
pgStatXactCommit > 0 || pgStatXactRollback > 0 || disconnect)
954+
pgstat_send_tabstat(&regular_msg, now);
952955
if (shared_msg.m_nentries > 0)
953-
pgstat_send_tabstat(&shared_msg);
956+
pgstat_send_tabstat(&shared_msg, now);
954957

955958
/* Now, send function statistics */
956959
pgstat_send_funcstats();
@@ -966,7 +969,7 @@ pgstat_report_stat(bool disconnect)
966969
* Subroutine for pgstat_report_stat: finish and send a tabstat message
967970
*/
968971
static void
969-
pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg)
972+
pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg, TimestampTz now)
970973
{
971974
int n;
972975
int len;
@@ -985,17 +988,44 @@ pgstat_send_tabstat(PgStat_MsgTabstat *tsmsg)
985988
tsmsg->m_xact_rollback = pgStatXactRollback;
986989
tsmsg->m_block_read_time = pgStatBlockReadTime;
987990
tsmsg->m_block_write_time = pgStatBlockWriteTime;
991+
992+
if (pgstat_should_report_connstat())
993+
{
994+
long secs;
995+
int usecs;
996+
997+
/*
998+
* pgLastSessionReportTime is initialized to MyStartTimestamp by
999+
* pgstat_report_connect().
1000+
*/
1001+
TimestampDifference(pgLastSessionReportTime, now, &secs, &usecs);
1002+
pgLastSessionReportTime = now;
1003+
tsmsg->m_session_time = (PgStat_Counter) secs * 1000000 + usecs;
1004+
tsmsg->m_active_time = pgStatActiveTime;
1005+
tsmsg->m_idle_in_xact_time = pgStatTransactionIdleTime;
1006+
}
1007+
else
1008+
{
1009+
tsmsg->m_session_time = 0;
1010+
tsmsg->m_active_time = 0;
1011+
tsmsg->m_idle_in_xact_time = 0;
1012+
}
9881013
pgStatXactCommit = 0;
9891014
pgStatXactRollback = 0;
9901015
pgStatBlockReadTime = 0;
9911016
pgStatBlockWriteTime = 0;
1017+
pgStatActiveTime = 0;
1018+
pgStatTransactionIdleTime = 0;
9921019
}
9931020
else
9941021
{
9951022
tsmsg->m_xact_commit = 0;
9961023
tsmsg->m_xact_rollback = 0;
9971024
tsmsg->m_block_read_time = 0;
9981025
tsmsg->m_block_write_time = 0;
1026+
tsmsg->m_session_time = 0;
1027+
tsmsg->m_active_time = 0;
1028+
tsmsg->m_idle_in_xact_time = 0;
9991029
}
10001030

10011031
n = tsmsg->m_nentries;
@@ -1363,49 +1393,6 @@ pgstat_drop_relation(Oid relid)
13631393
}
13641394
#endif /* NOT_USED */
13651395

1366-
1367-
/* ----------
1368-
* pgstat_send_connstats() -
1369-
*
1370-
* Tell the collector about session statistics.
1371-
* The parameter "disconnect" will be true when the backend exits.
1372-
* "last_report" is the last time we were called (0 if never).
1373-
* ----------
1374-
*/
1375-
static void
1376-
pgstat_send_connstats(bool disconnect, TimestampTz last_report)
1377-
{
1378-
PgStat_MsgConn msg;
1379-
long secs;
1380-
int usecs;
1381-
1382-
if (pgStatSock == PGINVALID_SOCKET || !pgstat_track_counts)
1383-
return;
1384-
1385-
pgstat_setheader(&msg.m_hdr, PGSTAT_MTYPE_CONNECTION);
1386-
msg.m_databaseid = MyDatabaseId;
1387-
1388-
/* session time since the last report */
1389-
TimestampDifference(((last_report == 0) ? MyStartTimestamp : last_report),
1390-
GetCurrentTimestamp(),
1391-
&secs, &usecs);
1392-
msg.m_session_time = secs * 1000000 + usecs;
1393-
1394-
msg.m_disconnect = disconnect ? pgStatSessionEndCause : DISCONNECT_NOT_YET;
1395-
1396-
msg.m_active_time = pgStatActiveTime;
1397-
pgStatActiveTime = 0;
1398-
1399-
msg.m_idle_in_xact_time = pgStatTransactionIdleTime;
1400-
pgStatTransactionIdleTime = 0;
1401-
1402-
/* report a new session only the first time */
1403-
msg.m_count = (last_report == 0) ? 1 : 0;
1404-
1405-
pgstat_send(&msg, sizeof(PgStat_MsgConn));
1406-
}
1407-
1408-
14091396
/* ----------
14101397
* pgstat_reset_counters() -
14111398
*
@@ -1744,6 +1731,63 @@ pgstat_report_tempfile(size_t filesize)
17441731
pgstat_send(&msg, sizeof(msg));
17451732
}
17461733

1734+
/* --------
1735+
* pgstat_report_connect() -
1736+
*
1737+
* Tell the collector about a new connection.
1738+
* --------
1739+
*/
1740+
void
1741+
pgstat_report_connect(Oid dboid)
1742+
{
1743+
PgStat_MsgConnect msg;
1744+
1745+
if (!pgstat_should_report_connstat())
1746+
return;
1747+
1748+
pgLastSessionReportTime = MyStartTimestamp;
1749+
1750+
pgstat_setheader(&msg.m_hdr, PGSTAT_MTYPE_CONNECT);
1751+
msg.m_databaseid = MyDatabaseId;
1752+
pgstat_send(&msg, sizeof(PgStat_MsgConnect));
1753+
}
1754+
1755+
/* --------
1756+
* pgstat_report_disconnect() -
1757+
*
1758+
* Tell the collector about a disconnect.
1759+
* --------
1760+
*/
1761+
static void
1762+
pgstat_report_disconnect(Oid dboid)
1763+
{
1764+
PgStat_MsgDisconnect msg;
1765+
1766+
if (!pgstat_should_report_connstat())
1767+
return;
1768+
1769+
pgstat_setheader(&msg.m_hdr, PGSTAT_MTYPE_DISCONNECT);
1770+
msg.m_databaseid = MyDatabaseId;
1771+
msg.m_cause = pgStatSessionEndCause;
1772+
pgstat_send(&msg, sizeof(PgStat_MsgDisconnect));
1773+
}
1774+
1775+
/* --------
1776+
* pgstat_should_report_connstats() -
1777+
*
1778+
* We report session statistics only for normal backend processes. Parallel
1779+
* workers run in parallel, so they don't contribute to session times, even
1780+
* though they use CPU time. Walsender processes could be considered here,
1781+
* but they have different session characteristics from normal backends (for
1782+
* example, they are always "active"), so they would skew session statistics.
1783+
* ----------
1784+
*/
1785+
static bool
1786+
pgstat_should_report_connstat(void)
1787+
{
1788+
return MyBackendType == B_BACKEND;
1789+
}
1790+
17471791
/* ----------
17481792
* pgstat_report_replslot() -
17491793
*
@@ -3363,8 +3407,12 @@ PgstatCollectorMain(int argc, char *argv[])
33633407
pgstat_recv_replslot(&msg.msg_replslot, len);
33643408
break;
33653409

3366-
case PGSTAT_MTYPE_CONNECTION:
3367-
pgstat_recv_connstat(&msg.msg_conn, len);
3410+
case PGSTAT_MTYPE_CONNECT:
3411+
pgstat_recv_connect(&msg.msg_connect, len);
3412+
break;
3413+
3414+
case PGSTAT_MTYPE_DISCONNECT:
3415+
pgstat_recv_disconnect(&msg.msg_disconnect, len);
33683416
break;
33693417

33703418
default:
@@ -4785,6 +4833,10 @@ pgstat_recv_tabstat(PgStat_MsgTabstat *msg, int len)
47854833
dbentry->n_block_read_time += msg->m_block_read_time;
47864834
dbentry->n_block_write_time += msg->m_block_write_time;
47874835

4836+
dbentry->total_session_time += msg->m_session_time;
4837+
dbentry->total_active_time += msg->m_active_time;
4838+
dbentry->total_idle_in_xact_time += msg->m_idle_in_xact_time;
4839+
47884840
/*
47894841
* Process all table entries in the message.
47904842
*/
@@ -5434,23 +5486,34 @@ pgstat_recv_replslot(PgStat_MsgReplSlot *msg, int len)
54345486
}
54355487

54365488
/* ----------
5437-
* pgstat_recv_connstat() -
5489+
* pgstat_recv_connect() -
54385490
*
5439-
* Process connection information.
5491+
* Process a CONNECT message.
54405492
* ----------
54415493
*/
54425494
static void
5443-
pgstat_recv_connstat(PgStat_MsgConn *msg, int len)
5495+
pgstat_recv_connect(PgStat_MsgConnect *msg, int len)
54445496
{
54455497
PgStat_StatDBEntry *dbentry;
54465498

54475499
dbentry = pgstat_get_db_entry(msg->m_databaseid, true);
5500+
dbentry->n_sessions++;
5501+
}
54485502

5449-
dbentry->n_sessions += msg->m_count;
5450-
dbentry->total_session_time += msg->m_session_time;
5451-
dbentry->total_active_time += msg->m_active_time;
5452-
dbentry->total_idle_in_xact_time += msg->m_idle_in_xact_time;
5453-
switch (msg->m_disconnect)
5503+
/* ----------
5504+
* pgstat_recv_disconnect() -
5505+
*
5506+
* Process a DISCONNECT message.
5507+
* ----------
5508+
*/
5509+
static void
5510+
pgstat_recv_disconnect(PgStat_MsgDisconnect *msg, int len)
5511+
{
5512+
PgStat_StatDBEntry *dbentry;
5513+
5514+
dbentry = pgstat_get_db_entry(msg->m_databaseid, true);
5515+
5516+
switch (msg->m_cause)
54545517
{
54555518
case DISCONNECT_NOT_YET:
54565519
case DISCONNECT_NORMAL:

‎src/backend/tcop/postgres.c

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4108,6 +4108,8 @@ PostgresMain(int argc, char *argv[],
41084108
if (IsUnderPostmaster && Log_disconnections)
41094109
on_proc_exit(log_disconnections, 0);
41104110

4111+
pgstat_report_connect(MyDatabaseId);
4112+
41114113
/* Perform initialization specific to a WAL sender process. */
41124114
if (am_walsender)
41134115
InitWalSender();

‎src/backend/utils/activity/backend_status.c

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -590,9 +590,9 @@ pgstat_report_activity(BackendState state, const char *cmd_str)
590590

591591
if (beentry->st_state == STATE_RUNNING ||
592592
beentry->st_state == STATE_FASTPATH)
593-
pgstat_count_conn_active_time(secs * 1000000 + usecs);
593+
pgstat_count_conn_active_time((PgStat_Counter) secs * 1000000 + usecs);
594594
else
595-
pgstat_count_conn_txn_idle_time(secs * 1000000 + usecs);
595+
pgstat_count_conn_txn_idle_time((PgStat_Counter) secs * 1000000 + usecs);
596596
}
597597

598598
/*

0 commit comments

Comments
 (0)