Re: log_postmaster_stats

On Thu, Jul 30, 2026 at 8:46 AM Jakub Wartak
<jakub(dot)wartak(at)enterprisedb(dot)com> wrote:
>
> On Tue, Jul 28, 2026 at 4:00 PM Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
> >
> > On Mon, Jul 27, 2026 at 2:47 AM Jakub Wartak
> > <jakub(dot)wartak(at)enterprisedb(dot)com> wrote:
> > > 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 think this is a good direction, but over the years I've acquired a
> > healthy skepticism of features where the documentation and the actual
> > behavior of the code drift apart like this. Since the feature name is
> > log_excess_connection_attempts, a user will tend to think that what
> > triggers the message is when there are a lot of connection attempts,
> > but it's actually trigger by high CPU usage or too much time passing
> > between consecutive points at which we consider logging the message.
>
> OK, I've renamed the CPU overload one to simply just log_postmaster_overloads
> and also added the log_postmaster_excess_connections=N for the reasons explained
> below.
>
> > Plus, checking the CPU usage like this is somewhat expensive, and I
> > doubt that high CPU usage over a 1 second period is even meaningful.
>
> getrusage() is pretty cheap actually as only use *if* that would be
> enabled by user + just called once every 1s (which itself compared
> to cap of 1-3 thousands of fork()/s is nothing I would say less than
> a noise?) + we use RUSAGE_SELF (so by definition it does not iterate on
> kernel side fo cpu time of all the possible children).
>
> > I suspect the right thing to do here is drop all the CPU usage stuff
> > and just make it a test for whether the connection rate is high. Then
> > you could also make the value of the parameter an integer, like:
> > log_excessive_connection_rate=100 to log whenever there are >=100
> > connection in 1 second. That gives the parameter a very specific
> > charter that is easy to guess even from just looking at the name. A
> > side benefit of this is that you could write a test that would pass
> > reliably; just set log_excessive_connection_rate=1 and try to connect.
> > 1 >= 1 so a message should appear.
>
> The problem with just the raw new sessions/s is that how the user is
> supposed to know to which value set it to? She/he could observe
> rate of pg_stat_database.{sessions,parallel_workers_launched}, and based
> to come up with average and then set it up to some value.
>
> So perhaps we could have two, (the main intention was to just stick to
> the CPU usage, but the v3 has bonus second GUC to allow what You just
> described). With CPU usage, I think people would agree that anything
> >=70-80% is clear sign of overload (so that's just nice on/off toggle).
> While with setting raw number of connections with
> log_postmaster_excess_connections I've myself reproduced <200-300
> connections/s taking 100% sys for postmaster and it would never occur
> to me that I would have to set it up to such _low_ value.
>
> Anyway please just take a look on [1] to see that it might be not even
> obvious that connection startup might be a problem, but if we would even
> have this on by default such cases would be fairly trivial to solve in
> like seconds (just read the log) and there are fairly more examples
> where postmaster bottleneck can be an issue (people running apps usually
> do not have visibiity tracing of avg/p95/p99 database connection times
> until their apps crap out with errors that those connections failed
> due timeouts).
>
> -J.
>
> [1] - https://www.postgresql.org/message-id/CAFbpF8OA44_UG%2BRYJcWH9WjF7E3GA6gka3gvH6nsrSnEe9H0NA%40mail.gmail.com

I've got another occurence where this could be useful, so this pushed me into
polishing this patch. It still has two log_postmaster_excess_connections and
log_postmaster_overloads and they are both useful.

v4 attached, changes since last time:
- reset stats more often (when GUCs where enabled single spurious LOG emission
happened with stats since the restart)
- add counting of accept()/fork() failures too (but not the max_conns hits as)
- convert "elapsed" from integer to double to make the math easier
- pgindent

One doubt I have is this: if both GUCs are enabled (with
log_postmaster_excess_connections set to e.g. value of 200), we get duplicate
LOG entries, but I thnk we could unitfy the LOG line in such case:

2026-11-09 12:06:30.773 CET [751665] LOG: postmaster potentially
overloaded, stats: avg 3179.96 conns/sec; 3178.96 disconns/sec; 0.00
conn errors/sec; 0.00 parallel workers started/sec; CPU: user: 0.02 s,
system: 0.97 s, elapsed: 1.00 s
2026-11-09 12:06:30.773 CET [751665] LOG: postmaster excessive
connections, stats: avg 3179.96 conns/sec; 3178.96 disconns/sec; 0.00
conn errors/sec; 0.00 parallel workers started/sec; CPU: user: 0.02 s,
system: 0.97 s, elapsed: 1.00 s
2026-11-09 12:06:31.773 CET [751665] LOG: postmaster potentially
overloaded, stats: avg 3177.37 conns/sec; 3179.37 disconns/sec; 0.00
conn errors/sec; 0.00 parallel workers started/sec; CPU: user: 0.02 s,
system: 0.97 s, elapsed: 1.00 s
2026-11-09 12:06:31.773 CET [751665] LOG: postmaster excessive
connections, stats: avg 3177.37 conns/sec; 3179.37 disconns/sec; 0.00
conn errors/sec; 0.00 parallel workers started/sec; CPU: user: 0.02 s,
system: 0.97 s, elapsed: 1.00 s
[..]

instead we could do "postmaster overloaded and getting excessive connections,
stats: (..)",

-J.