From 05b1f3eb7d7f7a760a53e75d7f37b040bdc12996 Mon Sep 17 00:00:00 2001 From: Jakub Wartak Date: Wed, 27 May 2026 11:39:21 +0200 Subject: [PATCH v4] Add log_postmaster_overloads and log_postmaster_excess_connections log_postmaster_overloads - Add possibility to log basic resource consumption, activity metrics and errors 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 | 99 ++++++++ src/backend/postmaster/bgworker.c | 10 + src/backend/postmaster/postmaster.c | 213 +++++++++++++++++- 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, 434 insertions(+), 2 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 a6a2df177f2..9ae5d2063d7 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8522,6 +8522,105 @@ 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 connection 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, or could not serve at least one incoming connection, + emits a message at LOG level + summarizing its recent activity. Since by design the postmaster is a + single process handling all new connections and parallel worker + launches, 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 conn errors/sec; 0.00 parallel workers started/sec; CPU: user: 0.01 s, system: 0.97 s, elapsed: 1.00 s + + + + conn errors counts connections the postmaster + could not serve: + + + + + a failed accept() system call, for example + because the postmaster ran out of file descriptors + + + + + a failure to start a backend process for the connection, for + example because fork() failed due to lack of + memory or process limits + + + + + a connection that was only given an error because the server was + starting up, shutting down, in recovery, or had no free child + process slot + + + + + Ordinary too many clients rejections caused by + are issued by a regular backend + process and are not counted. Note that a single parallel query may + register multiple workers. The final CPU portion + reports the postmaster's own resource usage over the same one second + window. 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 4aef037d5ae..81fcc55e2c5 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 f53aa9c404d..2e648449ee3 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,102 @@ 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 in time on CPU 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; + +/* pmstats_ru0.tv is the start of the (statistics) interval for log_postmaster_* GUCs */ +static PGRUsage pmstats_ru0; + +/* Running counts used by log_postmaster_* GUCs */ +static uint64 pmstats_new_connections = 0; +static uint64 pmstats_disconnections = 0; +static uint64 pmstats_connection_errors = 0; +static uint64 last_pmstats_connections = 0; +static uint64 last_pmstats_connection_errors = 0; +static uint64 last_pmstats_disconnections = 0; +static uint32 last_pmstats_parallel_regs = 0; + +static bool +pmstats_enabled(void) +{ + return log_postmaster_overloads || log_postmaster_excess_connections > 0; +} + +/* Reset stats when starting a new check interval */ +static void +pmstats_reset(void) +{ + last_pmstats_connections = pmstats_new_connections; + last_pmstats_disconnections = pmstats_disconnections; + last_pmstats_connection_errors = pmstats_connection_errors; + last_pmstats_parallel_regs = GetParallelWorkerRegisterCount(); + pg_rusage_init(&pmstats_ru0); +} + +/* + * Returns seconds elapsed between the start of the current check interval + * and the given time. + */ +static double +pmstats_elapsed(const struct timeval *now) +{ + return (double) (now->tv_sec - pmstats_ru0.tv.tv_sec) + + (double) (now->tv_usec - pmstats_ru0.tv.tv_usec) / 1000000.0; +} + +/* Returns how many milliseconds to sleep until the next check. */ +static int +pmstats_ms_to_next_check(void) +{ + struct timeval tv; + int64 elapsed_us, + remaining_us; + + gettimeofday(&tv, NULL); + elapsed_us = (int64) (tv.tv_sec - pmstats_ru0.tv.tv_sec) * 1000000 + + (tv.tv_usec - pmstats_ru0.tv.tv_usec); + remaining_us = (int64) PM_STATS_CHECK_INTERVAL * 1000000 - elapsed_us; + + /* Did the interval just started? */ + if (remaining_us >= (int64) PM_STATS_CHECK_INTERVAL * 1000000) + return PM_STATS_CHECK_INTERVAL * 1000; /* sleep full interval */ + + /* Are we already late? */ + if (remaining_us <= 0) + return 1; + + /* Convert us to ms, but round up */ + return (int) ((remaining_us + 999) / 1000); +} + bool log_hostname; /* for ps display and logging */ bool enable_bonjour = false; @@ -1635,10 +1732,15 @@ DetermineSleepTime(void) /* result of TimestampDifferenceMilliseconds is in [0, INT_MAX] */ ms = (int) TimestampDifferenceMilliseconds(GetCurrentTimestamp(), next_wakeup); + if (pmstats_enabled()) + ms = Min(ms, pmstats_ms_to_next_check()); return Min(60 * 1000, ms); } - return 60 * 1000; + if (pmstats_enabled()) + return Min(60 * 1000, pmstats_ms_to_next_check()); + else + return 60 * 1000; } /* @@ -1683,6 +1785,7 @@ ServerLoop(void) ConfigurePostmasterWaitSet(true); last_lockfile_recheck_time = last_touch_time = time(NULL); + pmstats_reset(); for (;;) { @@ -1724,7 +1827,13 @@ ServerLoop(void) ClientSocket s; if (AcceptConnection(events[i].fd, &s) == STATUS_OK) - BackendStartup(&s); + { + pmstats_new_connections++; + if (BackendStartup(&s) != STATUS_OK) + pmstats_connection_errors++; + } + else + pmstats_connection_errors++; /* We no longer need the open socket in this process */ if (s.sock != PGINVALID_SOCKET) @@ -1823,6 +1932,85 @@ 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 (pmstats_enabled()) + { + struct timeval tv; + double elapsed; + + gettimeofday(&tv, NULL); + elapsed = pmstats_elapsed(&tv); + + /* Did the clock go backwards? Then just start a new interval. */ + if (elapsed < 0.0) + { + pmstats_reset(); + } + else if (elapsed >= PM_STATS_CHECK_INTERVAL) + { + uint32 cur_parallel_regs = GetParallelWorkerRegisterCount(); + uint64 conn_delta = pmstats_new_connections - last_pmstats_connections; + uint64 disc_delta = pmstats_disconnections - last_pmstats_disconnections; + uint64 err_delta = pmstats_connection_errors - last_pmstats_connection_errors; + uint32 pqw_delta = cur_parallel_regs - last_pmstats_parallel_regs; + double conn_rate = (double) conn_delta / 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 || err_delta > 0) + { + ereport(LOG, + (errmsg("postmaster potentially overloaded, stats: avg %.2f conns/sec; %.2f disconns/sec; %.2f conn errors/sec; %.2f parallel workers started/sec; %s", + conn_rate, + (double) disc_delta / elapsed, + (double) err_delta / elapsed, + (double) pqw_delta / 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 conn errors/sec; %.2f parallel workers started/sec; %s", + conn_rate, + (double) disc_delta / elapsed, + (double) err_delta / elapsed, + (double) pqw_delta / elapsed, + pg_rusage_show(&pmstats_ru0)))); + } + + pmstats_reset(); + } + } } } @@ -2028,9 +2216,19 @@ process_pm_reload_request(void) if (Shutdown <= SmartShutdown) { + bool pmstats_was_enabled = pmstats_enabled(); + ereport(LOG, (errmsg("received SIGHUP, reloading configuration files"))); ProcessConfigFile(PGC_SIGHUP); + + /* + * If the postmaster stats checks were just enabled, start the first + * checks now rather than measuring since the last check (which could + * be start of the postmaster itself). + */ + if (!pmstats_was_enabled && pmstats_enabled()) + pmstats_reset(); SignalChildren(SIGHUP, btmask_all_except(B_DEAD_END_BACKEND)); /* Reload authentication config files too */ @@ -2622,6 +2820,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 @@ -3282,6 +3484,9 @@ PostmasterStateMachine(void) ShmemCallRequestCallbacks(); CreateSharedMemoryAndSemaphores(); + /* Start with fresh statistics */ + pmstats_reset(); + UpdatePMState(PM_STARTUP); /* Make sure we can perform I/O while starting up. */ @@ -3669,6 +3874,10 @@ BackendStartup(ClientSocket *client_sock) GetBackendTypeDesc(bn->bkend_type), (int) pid, (int) client_sock->sock))); + /* Potentiall fork() failures above are counted in parent ServerLoop() */ + if (cac != CAC_OK) + pmstats_connection_errors++; + /* * Everything's been successful, it's safe to add this backend to our list * of backends. diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index 1d0d73074a1..a255387a64c 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 01f98de8a9f..fc4b23d0a77 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -670,6 +670,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