On Thu, Jul 23, 2026 at 10:25 AM Jakub Wartak <[email protected]> wrote: > > On Mon, Jul 20, 2026 at 3:16 PM Robert Haas <[email protected]> wrote: [..]
After some quick offline follow-up chat with Robert last Thursday, he helped me to steer more this towards emergency logging in case of overloaded postmaster rather constant logging of postmaster statistics. One can think of it something like 'checkpoints happening too fast', but for postmaster. Now the GUC/concept is called log_excess_connection_attempts, however it is based on postmaster's CPU time or delay in getting CPU scheduled at all. I think name is nice, but one can argue it should be log_excess_postmaster_cpu_time too technically, but I find it way too long. I've did not wanted to clobber more the logging output, so the HINT line is not there, but now documentation has tip what to check (and btw it is off by default, so only people suspecting/debugging something would be getting any of this) There's one problem with github CI (and probably buildfarm), not being good place to test it (apparently ~8 VCPUs are not enough to overload with pgbench --connect the postamster), so that test is there, but commented out mostly. -J.
From 232d8894c78a6757082218e703057b16cf145f78 Mon Sep 17 00:00:00 2001 From: Jakub Wartak <[email protected]> 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 <[email protected]> Reviewed-by: Quan Zongliang <[email protected]> Reviewed-by: Robert Haas <[email protected]> --- 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 ' </listitem> </varlistentry> + <varlistentry id="guc-log-excess-connection-attempts" xreflabel="log_excess_connection_attempts"> + <term><varname>log_excess_connection_attempts</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>log_excess_connection_attempts</varname></primary> + <secondary>configuration parameter</secondary> + </indexterm> + </term> + <listitem> + <para> + 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 <literal>LOG</literal> 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: + <screen> + 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 + </screen> + Note that a single parallel query may register multiple workers. The + final <literal>CPU</literal> portion reports postmaster process + resource usage over the same window (over 1 second). + </para> + <para> + The default is <literal>off</literal>. This parameter can only be + set in the <filename>postgresql.conf</filename> file or on the + server command line. + </para> + <tip> + <para> + 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. + </para> + </tip> + </listitem> + </varlistentry> <varlistentry id="guc-log-recovery-conflict-waits" xreflabel="log_recovery_conflict_waits"> <term><varname>log_recovery_conflict_waits</varname> (<type>boolean</type>) 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
