From 232d8894c78a6757082218e703057b16cf145f78 Mon Sep 17 00:00:00 2001 From: Jakub Wartak Date: Wed, 27 May 2026 11:39:21 +0200 Subject: [PATCH v2] Add log_excess_connection_attempts Add possibility to log basic resource consumption and activity metrics by the postmaster process in cases where it would be overloaded (defined as 75% or getting late on CPU). Author: Jakub Wartak Reviewed-by: Quan Zongliang Reviewed-by: Robert Haas --- doc/src/sgml/config.sgml | 40 ++++++ src/backend/postmaster/bgworker.c | 10 ++ src/backend/postmaster/postmaster.c | 115 +++++++++++++++++- src/backend/utils/misc/guc_parameters.dat | 7 ++ src/backend/utils/misc/postgresql.conf.sample | 2 + src/include/postmaster/bgworker_internals.h | 1 + src/include/postmaster/postmaster.h | 1 + src/test/postmaster/meson.build | 1 + .../t/005_log_excess_connection_attempts.pl | 78 ++++++++++++ 9 files changed, 252 insertions(+), 3 deletions(-) create mode 100644 src/test/postmaster/t/005_log_excess_connection_attempts.pl diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 73cc0412330..0bc6e2d1587 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8381,6 +8381,46 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' + + log_excess_connection_attempts (boolean) + + log_excess_connection_attempts + configuration parameter + + + + + If enabled, the postmaster checks its own resource usage every + second, and if it has used more than 75% of one CPU core during + that second, emits a message at LOG level + summarizing its recent activity. Since by the design the postmaster is + single process handling all new connections (or parallel workers), + constant CPU usage above this threshold indicates that it may + be struggling to keep up, typically because of a very high + rate of incoming connection attempts. A sample message looks like: + + postmaster potentially overloaded, stats: avg 2905.00 conns/sec; 2904.00 disconns/sec; 0.00 parallel workers started/sec; + CPU: user: 0.01 s, system: 0.97 s, elapsed: 1.00 + + Note that a single parallel query may register multiple workers. The + final CPU portion reports postmaster process + resource usage over the same window (over 1 second). + + + The default is off. This parameter can only be + set in the postgresql.conf file or on the + server command line. + + + + If you are receiving warnings about potentially overloaded postmaster, + be sure to investigate the application, their connection pools and usage + of independent connection poolers. Be also sure to double-check if the + huge pages are used and if the OS is not being overloaded. + + + + log_recovery_conflict_waits (boolean) diff --git a/src/backend/postmaster/bgworker.c b/src/backend/postmaster/bgworker.c index 2e4acad4f00..e2455e13599 100644 --- a/src/backend/postmaster/bgworker.c +++ b/src/backend/postmaster/bgworker.c @@ -239,6 +239,16 @@ BackgroundWorkerShmemInit(void *arg) } } +/* + * Return the total count of parallel-worker registrations seen since + * startup by doing unlocked read (for stats it should be good enough). + */ +uint32 +GetParallelWorkerRegisterCount(void) +{ + return BackgroundWorkerData->parallel_register_count; +} + /* * Search the postmaster's backend-private list of RegisteredBgWorker objects * for the one that maps to the given slot number. diff --git a/src/backend/postmaster/postmaster.c b/src/backend/postmaster/postmaster.c index 90c7c4528e8..2f1aed588f4 100644 --- a/src/backend/postmaster/postmaster.c +++ b/src/backend/postmaster/postmaster.c @@ -120,6 +120,7 @@ #include "tcop/tcopprot.h" #include "utils/datetime.h" #include "utils/memutils.h" +#include "utils/pg_rusage.h" #include "utils/pidfile.h" #include "utils/timestamp.h" #include "utils/varlena.h" @@ -241,6 +242,34 @@ bool EnableSSL = false; int PreAuthDelay = 0; int AuthenticationTimeout = 60; +/* + * If enabled, check postmaster CPU usage every PM_STATS_CHECK_INTERVAL + * seconds. + */ +bool log_excess_connection_attempts = false; + +/* How often to check when log_excess_connection_attempts is on */ +#define PM_STATS_CHECK_INTERVAL 1 + +/* + * Since the postmaster is single process, consider it overloaded when + * it has used more than this fraction of one core during the check + * interval. + */ +#define PM_STATS_CPU_THRESHOLD 0.75 + +/* + * Alternatively, also log if the check itself ran this much later than + * intended (as a multipler of the PM_STATS_CHECK_INTERVAL above). Postmaster + * that isn't getting scheduled promptly in time to run checks on schedule + * is a sign of trouble even if it is not itself burning much CPU. + */ +#define PM_STATS_ELAPSED_LATE_FACTOR 1.2 + +/* Running counts used by log_excess_connection_attempts. */ +static uint64 pmstats_new_connections = 0; +static uint64 pmstats_disconnections = 0; + bool log_hostname; /* for ps display and logging */ bool enable_bonjour = false; @@ -1636,10 +1665,15 @@ DetermineSleepTime(void) /* result of TimestampDifferenceMilliseconds is in [0, INT_MAX] */ ms = (int) TimestampDifferenceMilliseconds(GetCurrentTimestamp(), next_wakeup); + if (log_excess_connection_attempts) + ms = Min(ms, PM_STATS_CHECK_INTERVAL * 1000); return Min(60 * 1000, ms); } - return 60 * 1000; + if (log_excess_connection_attempts) + return Min(60 * 1000, PM_STATS_CHECK_INTERVAL * 1000); + else + return 60 * 1000; } /* @@ -1678,12 +1712,21 @@ static int ServerLoop(void) { time_t last_lockfile_recheck_time, - last_touch_time; + last_touch_time, + last_pmstats_time; + uint64 last_pmstats_connections = 0; + uint64 last_pmstats_disconnections = 0; + uint32 last_pmstats_parallel_regs = 0; + PGRUsage pmstats_ru0; WaitEvent events[MAXLISTEN]; int nevents; ConfigurePostmasterWaitSet(true); - last_lockfile_recheck_time = last_touch_time = time(NULL); + last_lockfile_recheck_time = last_touch_time = last_pmstats_time = time(NULL); + last_pmstats_connections = pmstats_new_connections; + last_pmstats_disconnections = pmstats_disconnections; + last_pmstats_parallel_regs = GetParallelWorkerRegisterCount(); + pg_rusage_init(&pmstats_ru0); for (;;) { @@ -1725,7 +1768,10 @@ ServerLoop(void) ClientSocket s; if (AcceptConnection(events[i].fd, &s) == STATUS_OK) + { BackendStartup(&s); + pmstats_new_connections++; + } /* We no longer need the open socket in this process */ if (s.sock != PGINVALID_SOCKET) @@ -1824,6 +1870,65 @@ ServerLoop(void) TouchSocketLockFiles(); last_touch_time = now; } + + /* + * Optionally check periodically whether the postmaster is short + * of CPU, and if so, log connection and resource usage statistics + * to help diagnose the cause (e.g. a flood of connection + * attempts). + */ + if (log_excess_connection_attempts && + now - last_pmstats_time >= PM_STATS_CHECK_INTERVAL) + { + time_t elapsed = now - last_pmstats_time; + uint32 cur_parallel_regs = GetParallelWorkerRegisterCount(); + + /* + * Just to be on safe side: emit LOG message only in the case of + * positive elapsed time (to avoid potential divisions by zero + * in case of time jumping backwards). + */ + if (elapsed > 0) + { + PGRUsage cur_ru; + double cpu_seconds; + + /* + * The postmaster is single backend, so treat it as short + * of CPU whenever either of two symptoms is observed: it + * has burned more than PM_STATS_CPU_THRESHOLD of one core + * over the elapsed time, or the check itself is running + * much later than the intended PM_STATS_CHECK_INTERVAL. + */ + pg_rusage_init(&cur_ru); + cpu_seconds = + (cur_ru.ru.ru_utime.tv_sec - pmstats_ru0.ru.ru_utime.tv_sec) + + (cur_ru.ru.ru_utime.tv_usec - pmstats_ru0.ru.ru_utime.tv_usec) / 1000000.0 + + (cur_ru.ru.ru_stime.tv_sec - pmstats_ru0.ru.ru_stime.tv_sec) + + (cur_ru.ru.ru_stime.tv_usec - pmstats_ru0.ru.ru_stime.tv_usec) / 1000000.0; + + if (cpu_seconds > PM_STATS_CPU_THRESHOLD * elapsed || + elapsed > PM_STATS_ELAPSED_LATE_FACTOR * PM_STATS_CHECK_INTERVAL) + { + uint64 conn_delta = pmstats_new_connections - last_pmstats_connections; + uint64 disc_delta = pmstats_disconnections - last_pmstats_disconnections; + uint32 pqw_delta = cur_parallel_regs - last_pmstats_parallel_regs; + + ereport(LOG, + (errmsg("postmaster potentially overloaded, stats: avg %.2f conns/sec; %.2f disconns/sec; %.2f parallel workers started/sec; %s", + (double) conn_delta / (double) elapsed, + (double) disc_delta / (double) elapsed, + (double) pqw_delta / (double) elapsed, + pg_rusage_show(&pmstats_ru0)))); + } + } + + last_pmstats_connections = pmstats_new_connections; + last_pmstats_disconnections = pmstats_disconnections; + last_pmstats_parallel_regs = cur_parallel_regs; + last_pmstats_time = now; + pg_rusage_init(&pmstats_ru0); + } } } @@ -2607,6 +2712,10 @@ CleanupBackend(PMChild *bp, else procname = _(GetBackendTypeDesc(bp->bkend_type)); + /* Count external (client or walsender) backend exits for stats. */ + if (IsExternalConnectionBackend(bp->bkend_type)) + pmstats_disconnections++; + /* * If a backend dies in an ugly way then we must signal all other backends * to quickdie. If exit status is zero (normal) or one (FATAL exit), we diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index afaa058b046..5b7cdd45a72 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -1698,6 +1698,13 @@ options => 'log_error_verbosity_options', }, +{ name => 'log_excess_connection_attempts', type => 'bool', context => 'PGC_SIGHUP', group => 'LOGGING_WHAT', + short_desc => 'Logs postmaster stats once per second when it is short of CPU.', + long_desc => 'If the postmaster has signs of being overloaded log message summarizing its recent activity.', + variable => 'log_excess_connection_attempts', + boot_val => 'false', +}, + { name => 'log_executor_stats', type => 'bool', context => 'PGC_SUSET', group => 'STATS_MONITORING', short_desc => 'Writes executor performance statistics to the server log.', variable => 'log_executor_stats', diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index ac38cddaaf9..0a86d560dbb 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -666,6 +666,8 @@ # e.g. '<%u%%%d> ' #log_lock_waits = on # log lock waits >= deadlock_timeout #log_lock_failures = off # log lock failures +#log_excess_connection_attempts = off # log postmaster stats once per + # second when it is CPU-bound #log_recovery_conflict_waits = off # log standby recovery conflict waits # >= deadlock_timeout #log_parameter_max_length = -1 # when logging statements, limit logged diff --git a/src/include/postmaster/bgworker_internals.h b/src/include/postmaster/bgworker_internals.h index b6261bc01df..a75eab3614c 100644 --- a/src/include/postmaster/bgworker_internals.h +++ b/src/include/postmaster/bgworker_internals.h @@ -48,6 +48,7 @@ extern void ReportBackgroundWorkerExit(RegisteredBgWorker *rw); extern void BackgroundWorkerStopNotifications(pid_t pid); extern void ForgetUnstartedBackgroundWorkers(void); extern void ResetBackgroundWorkerCrashTimes(void); +extern uint32 GetParallelWorkerRegisterCount(void); /* Entry point for background worker processes */ pg_noreturn extern void BackgroundWorkerMain(const void *startup_data, size_t startup_data_len); diff --git a/src/include/postmaster/postmaster.h b/src/include/postmaster/postmaster.h index 716b4c912b3..4fca8caca42 100644 --- a/src/include/postmaster/postmaster.h +++ b/src/include/postmaster/postmaster.h @@ -63,6 +63,7 @@ extern PGDLLIMPORT char *ListenAddresses; extern PGDLLIMPORT bool ClientAuthInProgress; extern PGDLLIMPORT int PreAuthDelay; extern PGDLLIMPORT int AuthenticationTimeout; +extern PGDLLIMPORT bool log_excess_connection_attempts; extern PGDLLIMPORT bool log_hostname; extern PGDLLIMPORT bool enable_bonjour; extern PGDLLIMPORT char *bonjour_name; diff --git a/src/test/postmaster/meson.build b/src/test/postmaster/meson.build index fa30883b601..4df634cd5fc 100644 --- a/src/test/postmaster/meson.build +++ b/src/test/postmaster/meson.build @@ -10,6 +10,7 @@ tests += { 't/002_connection_limits.pl', 't/003_start_stop.pl', 't/004_negotiate.pl', + 't/005_log_excess_connection_attempts.pl', ], }, } diff --git a/src/test/postmaster/t/005_log_excess_connection_attempts.pl b/src/test/postmaster/t/005_log_excess_connection_attempts.pl new file mode 100644 index 00000000000..07a6000e131 --- /dev/null +++ b/src/test/postmaster/t/005_log_excess_connection_attempts.pl @@ -0,0 +1,78 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Verify that log_excess_connection_attempts does not spam the log with +# "postmaster potentially overloaded, stats:" log lines while the postmaster +# is idle. It is only supposed to log once the postmaster is nearly at +# the edge of single CPU core capacity. + +use strict; +use warnings FATAL => 'all'; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +# Best-effort detection of the number of CPUs available +sub get_cpus_num +{ + my $ncpus; + + if ($windows_os) + { + $ncpus = $ENV{NUMBER_OF_PROCESSORS}; + } + else + { + $ncpus = `nproc 2>/dev/null`; + chomp $ncpus if defined $ncpus; + if (!defined($ncpus) || $ncpus !~ /^\d+$/) + { + $ncpus = `sysctl -n hw.ncpu 2>/dev/null`; + chomp $ncpus if defined $ncpus; + } + } + + return $ncpus if defined($ncpus) && $ncpus =~ /^\d+$/ && $ncpus > 0; + # Return there is 16 VCPUs as fallback, so that we can that we can + # hopefully overloaded postmaster, but we don't really know, so + # hopefully that's enough. + return 16; +} + +my $clients = get_cpus_num() * 2; +note("using $clients pgbench clients"); + +my $node = PostgreSQL::Test::Cluster->new('primary'); +$node->init; +$node->append_conf( + 'postgresql.conf', qq( +log_excess_connection_attempts = on +log_connections = off +log_statement = ddl +max_connections = ) . ($clients + 10)); +$node->start; + +# Save current offset (size) of the logfile +my $offset = -s $node->logfile; +my $stats_re = + qr/postmaster potentially overloaded, stats: avg .* conns\/sec/; + +# Give the postmaster some time to have a chance to (wrongly) +# emit the stats line, then check it did not log anything. +$node->safe_psql('postgres', 'SELECT 1'); +sleep 2; +ok( !$node->log_contains($stats_re, $offset), + 'postmaster stats line not emitted while postmaster is not short of CPU' +); + +# Flood the postmaster for 2 seconds and check if the warning got emitted +# This fails on CI and probably buildfram due to not enough VCPUs to saturate +# postmaster, so it is commented out. +#$node->pgbench('--initialize --quiet --scale=1', 0, [], [], +# 'set up pgbench_accounts table'); +#$node->pgbench("--connect -c$clients -j$clients -T 2 -S -n", 0, [], [], +# 'pgbench --connect run to put stress on the postmaster'); +#$node->wait_for_log($stats_re, $offset); +#pass('postmaster stats line emitted while postmaster is short of CPU'); + +$node->stop; +done_testing(); -- 2.43.0