From 7b737073ddeef3afda2b927050ea8bb74204644f Mon Sep 17 00:00:00 2001 From: Jakub Wartak Date: Wed, 27 May 2026 11:39:21 +0200 Subject: [PATCH v3] Add log_postmaster_overloads and log_postmaster_excess_connections log_postmaster_overloads - 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). log_postmaster_excess_connections - Allow logging the same postmaster diagnostic stats just based just on the rate of new connections accepted per second, independent of the postmaster's own CPU usage. This GUC allows detecting connection storms even before the postmaster is not fully saturated. Author: Jakub Wartak Reviewed-by: Robert Haas Reviewed-by: Quan Zongliang Discussion: https://postgr.es/m/CAKZiRmxeTNAe_VZ9m%3Drt%3D5155mvL%3DCFsQ4ENJWhuUdgMe%3D_Udg%40mail.gmail.com --- doc/src/sgml/config.sgml | 68 +++++++++ src/backend/postmaster/bgworker.c | 10 ++ src/backend/postmaster/postmaster.c | 139 +++++++++++++++++- src/backend/utils/misc/guc_parameters.dat | 16 ++ src/backend/utils/misc/postgresql.conf.sample | 5 + src/include/postmaster/bgworker_internals.h | 1 + src/include/postmaster/postmaster.h | 2 + src/test/postmaster/meson.build | 1 + src/test/postmaster/t/005_log_postmaster.pl | 89 +++++++++++ 9 files changed, 328 insertions(+), 3 deletions(-) create mode 100644 src/test/postmaster/t/005_log_postmaster.pl diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 73cc0412330..128a8933adb 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8381,6 +8381,74 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' + + log_postmaster_excess_connections (integer) + + log_postmaster_excess_connections + configuration parameter + + + + + If set to a positive value, the postmaster checks once per second + how many new connections it accepted during that second, and if + that rate exceeds this many connections per second, emits the same + LOG-level message as + does. This can help + detect cconnection storms even in cases where the postmaster is not + overloaded. + + + The default is 0, which disables this check. + This parameter can only be set in the + postgresql.conf file or on the server + command line. + + + + + + log_postmaster_overloads (boolean) + + log_postmaster_overloads + 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). See also + , which emits + the same message based just on the incoming connection rate. + + + 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..85fc3b4f1fe 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,41 @@ bool EnableSSL = false; int PreAuthDelay = 0; int AuthenticationTimeout = 60; +/* + * If enabled, check postmaster CPU usage every PM_STATS_CHECK_INTERVAL + * seconds. + */ +bool log_postmaster_overloads = false; + +/* How often to check when log_postmaster_overloads 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 + +/* + * If positive, log when the rate of new connections accepted during the + * preceding PM_STATS_CHECK_INTERVAL exceeds this many connections per + * second. 0 disables this check. + */ +int log_postmaster_excess_connections = 0; + +/* Running counts used by log_postmaster_overloads / log_postmaster_excess_connections. */ +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 +1672,15 @@ DetermineSleepTime(void) /* result of TimestampDifferenceMilliseconds is in [0, INT_MAX] */ ms = (int) TimestampDifferenceMilliseconds(GetCurrentTimestamp(), next_wakeup); + if (log_postmaster_overloads || log_postmaster_excess_connections > 0) + ms = Min(ms, PM_STATS_CHECK_INTERVAL * 1000); return Min(60 * 1000, ms); } - return 60 * 1000; + if (log_postmaster_overloads || log_postmaster_excess_connections > 0) + return Min(60 * 1000, PM_STATS_CHECK_INTERVAL * 1000); + else + return 60 * 1000; } /* @@ -1678,12 +1719,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 +1775,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 +1877,82 @@ ServerLoop(void) TouchSocketLockFiles(); last_touch_time = now; } + + /* + * Optionally check periodically whether the postmaster is short of + * CPU or is being handed an excessive rate of new connections, and + * if so, log connection and resource usage statistics to help + * diagnose the root cause (e.g. a flood of connection attempts or slow fork()). + */ + if ((log_postmaster_overloads || log_postmaster_excess_connections > 0) && + 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) + { + 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; + double conn_rate = (double) conn_delta / (double) elapsed; + 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 (log_postmaster_overloads) + { + bool cpu_overloaded; + + cpu_overloaded = (cpu_seconds > PM_STATS_CPU_THRESHOLD * elapsed || + elapsed > PM_STATS_ELAPSED_LATE_FACTOR * PM_STATS_CHECK_INTERVAL); + if (cpu_overloaded) + { + ereport(LOG, + (errmsg("postmaster potentially overloaded, stats: avg %.2f conns/sec; %.2f disconns/sec; %.2f parallel workers started/sec; %s", + conn_rate, + (double) disc_delta / (double) elapsed, + (double) pqw_delta / (double) elapsed, + pg_rusage_show(&pmstats_ru0)))); + } + } + + if (log_postmaster_excess_connections > 0 && + conn_rate > log_postmaster_excess_connections) { + + ereport(LOG, + (errmsg("postmaster excessive connections, stats: avg %.2f conns/sec; %.2f disconns/sec; %.2f parallel workers started/sec; %s", + conn_rate, + (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 +2736,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..97fdde090e1 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -1820,6 +1820,22 @@ check_hook => 'check_stage_log_stats', }, +{ name => 'log_postmaster_excess_connections', type => 'int', context => 'PGC_SIGHUP', group => 'LOGGING_WHAT', + short_desc => 'Logs postmaster stats once per second when the rate of new connections exceeds this value.', + long_desc => '0 disables this check.', + variable => 'log_postmaster_excess_connections', + boot_val => '0', + min => '0', + max => 'INT_MAX', +}, + +{ name => 'log_postmaster_overloads', 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_postmaster_overloads', + boot_val => 'false', +}, + { name => 'log_recovery_conflict_waits', type => 'bool', context => 'PGC_SIGHUP', group => 'LOGGING_WHAT', short_desc => 'Logs standby recovery conflict waits.', variable => 'log_recovery_conflict_waits', diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index ac38cddaaf9..8bb6a84dd46 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -666,6 +666,11 @@ # e.g. '<%u%%%d> ' #log_lock_waits = on # log lock waits >= deadlock_timeout #log_lock_failures = off # log lock failures +#log_postmaster_overloads = off # log postmaster stats once per + # second when it is CPU-bound +#log_postmaster_excess_connections = 0 # log postmaster stats once per + # second when new connection rate + # exceeds this value; 0 disables #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..bac3b630e97 100644 --- a/src/include/postmaster/postmaster.h +++ b/src/include/postmaster/postmaster.h @@ -63,6 +63,8 @@ extern PGDLLIMPORT char *ListenAddresses; extern PGDLLIMPORT bool ClientAuthInProgress; extern PGDLLIMPORT int PreAuthDelay; extern PGDLLIMPORT int AuthenticationTimeout; +extern PGDLLIMPORT bool log_postmaster_overloads; +extern PGDLLIMPORT int log_postmaster_excess_connections; 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..7b64cb4d2f0 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_postmaster.pl', ], }, } diff --git a/src/test/postmaster/t/005_log_postmaster.pl b/src/test/postmaster/t/005_log_postmaster.pl new file mode 100644 index 00000000000..1999d2b27a2 --- /dev/null +++ b/src/test/postmaster/t/005_log_postmaster.pl @@ -0,0 +1,89 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +# Verify that log_postmaster_overloads 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. Also test +# log_postmaster_excess_connections as it is very similiar. + +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_postmaster_overloads = on +log_postmaster_excess_connections = 2 +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/; + +# 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'); + + +# Try out the log_postmaster_excessive_connections +$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'); +$stats_re = qr/postmaster excessive connections/; +$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