log_postmaster_stats

On 5/27/26 7:39 PM, Jakub Wartak wrote:

Hi -hackers,

We seem to have certain observability about postmaster
(pg_stat_database.{sessions,parallel_workers_launched}), but we do not have
pre-exisiting way to asses how much postmaster was really busy back in the
past. Even checkpointer (log_checkpoints) or startup recovery code is reporting
better what they were doing. One can say we have log_connections, yet bigger
shops cannot afford to log_connections all the time to count what happened
some time ago (and that can cumbersome anyway).

The attached patch introduces log_postmaster_stats in the same way we do have
log_startup_progress_interval, e.g. when set to 10 (seconds), it will show this
during artificial connection storm (log produced every 10s):

LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 10.00 s
LOG: postmaster stats: avg 1834.30 conns/sec; 1833.60 disconns/sec;
0.00 parallel workers started/sec; CPU: user: 0.12 s, system: 4.75 s,
elapsed: 9.96 s
LOG: postmaster stats: avg 1055.75 conns/sec; 1056.25 disconns/sec;
0.00 parallel workers started/sec; CPU: user: 0.12 s, system: 4.27 s,
elapsed: 16.25 s
LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 13.82 s
LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 10.00 s

The interesting thing above is that the elapsed time is 6s (with the
setting at 10s), then one
can already tell there was a probem.

When the database is idle for a long time. Will keep outputting

LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: ...
LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: ...
LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: ...

Could it be considered to reduce the output frequency when conn_delta,
disc_delta and pqw_delta are all zero?
Or until a new connection is established, then output the log for the
idle period at one time. Just like:

LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 1hours 10min 32s
LOG: postmaster stats: avg 0.30 conns/sec; 0.20 disconns/sec; 1.10
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 10.00 s

--
Quan Zongliang

On Wed, Jun 10, 2026 at 6:10 AM Quan Zongliang <quanzongliang@yeah.net> wrote:
[..]

When the database is idle for a long time. Will keep outputting

LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: ...
LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: ...
LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: ...

Could it be considered to reduce the output frequency when conn_delta,
disc_delta and pqw_delta are all zero?
Or until a new connection is established, then output the log for the
idle period at one time. Just like:

LOG: postmaster stats: avg 0.00 conns/sec; 0.00 disconns/sec; 0.00
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 1hours 10min 32s
LOG: postmaster stats: avg 0.30 conns/sec; 0.20 disconns/sec; 1.10
parallel workers started/sec; CPU: user: 0.00 s, system: 0.00 s,
elapsed: 10.00 s

Hi Quan,

thanks for trying out the patch! To be honest, I don't have opinion on
this, we could do that if there's community agreement to do this (or
some committer wants it this way or that way), but right now e.g.
checkpoint_timeout (which serves similiar purpose) does not behave
like that and always logs stuff and I was been told we should do
things consistently.

As for reducing logs volume, I think one could just use threshold
of 1 or 10 minutes (but while assessing some production issues one
could bump it down to every 1s temporarily just to have data to have
much better understandind what was system/postmaster doing).

-J.

On Wed, Jun 10, 2026 at 3:24 AM Jakub Wartak
<jakub.wartak@enterprisedb.com> wrote:

thanks for trying out the patch! To be honest, I don't have opinion on
this, we could do that if there's community agreement to do this (or
some committer wants it this way or that way), but right now e.g.
checkpoint_timeout (which serves similiar purpose) does not behave
like that and always logs stuff and I was been told we should do
things consistently.

As for reducing logs volume, I think one could just use threshold
of 1 or 10 minutes (but while assessing some production issues one
could bump it down to every 1s temporarily just to have data to have
much better understandind what was system/postmaster doing).

Well, on the immediate question, I think omitting the line altogether
when all the counters were zero would be sensible. I don't see who
would be helped by bloating the log volume in such a case.

But I would be really surprised if the overall design of this feature
didn't draw objections. I think what we normally do for features of
this type is include the relevant information in the cumulative
statistics system, and then leave it up to the user to decide how
often they want to poll the counters and how they want to summarize or
visualize the advancement of those counters. One could certainly make
an argument that having the information go to the log is a superior
user experience for people who don't need want, or need the complexity
of, an external tool. But it's going to be hard to justify why this
particular feature should be designed differently than all the other
features that do similar things.

--
Robert Haas
EDB: http://www.enterprisedb.com

On Mon, Jul 20, 2026 at 3:16 PM Robert Haas <robertmhaas@gmail.com> wrote:

On Wed, Jun 10, 2026 at 3:24 AM Jakub Wartak
<jakub.wartak@enterprisedb.com> wrote:

thanks for trying out the patch! To be honest, I don't have opinion on
this, we could do that if there's community agreement to do this (or
some committer wants it this way or that way), but right now e.g.
checkpoint_timeout (which serves similiar purpose) does not behave
like that and always logs stuff and I was been told we should do
things consistently.

As for reducing logs volume, I think one could just use threshold
of 1 or 10 minutes (but while assessing some production issues one
could bump it down to every 1s temporarily just to have data to have
much better understandind what was system/postmaster doing).

Well, on the immediate question, I think omitting the line altogether
when all the counters were zero would be sensible. I don't see who
would be helped by bloating the log volume in such a case.

OK, makes sense too.

But I would be really surprised if the overall design of this feature
didn't draw objections. I think what we normally do for features of
this type is include the relevant information in the cumulative
statistics system, and then leave it up to the user to decide how
often they want to poll the counters and how they want to summarize or
visualize the advancement of those counters. One could certainly make
an argument that having the information go to the log is a superior
user experience for people who don't need want, or need the complexity
of, an external tool. But it's going to be hard to justify why this
particular feature should be designed differently than all the other
features that do similar things.

As I understand, You are trying to say that for every kind of observability
metric there might be, we always seem to have choice of 3:

a. put the metrics / fact into logs, e.g. log_startup_progress_interval
(please see 9ce346eabf35), or log establishing every new connection
b. or put it into pg_stat* subsystem: e.g. like pg_stat_database.sessions (so
already there somewhat)
c. not have it at all

The thing is that for single-threaded subsystems (postmaster,
postmaster/recovery, bgwriter, checkpointer, walsender) we seem not to have
any even approximate way of signaling to the DBAs the overload of the single
core capacity by those processes, especially on very active DBs (it's hard for
people to spot temporary spikes of single 100% CPU postmaster if one is having
like dozens of 100% CPU active backends all time on 128 VCPUs+; lots of people
miss this). So, the idea here is to have have something like easily accessible
built-in "pidstat 1" tracking at least for critical postmaster. The patch logs
something like:
LOG: postmaster stats: avg 1055.75 conns/sec; 0.00 parallel workers
started/sec; CPU: user: 0.12 s, system: 4.27 s, ..
but my intention was more to capture the rusage data itself over date/time
rather than the conns/sec metric itself, but it is free addition and allows
easy correlation to the root-cause itself (parallel workers or new sessions).
Most of the time it is going to be flood of connections, but this $thread is
direct outcome of third reason: inefficiencies in fork() with 512GB s_b and
using kernel < 6.x (pre 6.0/or pre 6.5 kernels seems to lack certain hugetlb
optimizations for fork() + MAP_HUGEPAGES_2GB|MAP_SHARED), but there are also
other reasons why postmaster may really can suck in the field apparently,
please see [1]/messages/by-id/a5916f83-de79-4a40-933a-fb0d9ba2f5a0@app.fastmail.com , especially the "For an example of scale, we have seen users with low connection rates (<= 5 / minute) suddenly spike to between 2000 and 3000 connect requests per minute until the system grinds to a halt." (all due to PQ workers)

So, cumuluative statistics seem to be never tracking historical information by
design and it seem to be never tracking CPU usage of anything (we could
capture maximum observed CPU usage for postmaster though between
pg_stat_reset*()s, not sure it would be good idea).

Those are related codepaths which kind of also inspired this:
1. xlogrecovery.c has errmsg("redo done at %X/%08X system usage: %s", ..
pg_rusage_show(&ru0)));
2. analyze/vacuum also log the same rusage()
3. checkpointer already does kind of similiar thing with "checkpoint complete:
time .. write=0.003 s, sync=0.001 s, total=0.017 s; "

-J.

[1]: /messages/by-id/a5916f83-de79-4a40-933a-fb0d9ba2f5a0@app.fastmail.com , especially the "For an example of scale, we have seen users with low connection rates (<= 5 / minute) suddenly spike to between 2000 and 3000 connect requests per minute until the system grinds to a halt." (all due to PQ workers)
/messages/by-id/a5916f83-de79-4a40-933a-fb0d9ba2f5a0@app.fastmail.com
,
especially the "For an example of scale, we have seen users with low connection
rates (<= 5 / minute) suddenly spike to between 2000 and 3000 connect
requests per
minute until the system grinds to a halt." (all due to PQ workers)

On Thu, Jul 23, 2026 at 10:25 AM Jakub Wartak
<jakub.wartak@enterprisedb.com> wrote:

On Mon, Jul 20, 2026 at 3:16 PM Robert Haas <robertmhaas@gmail.com> 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.

On Mon, Jul 27, 2026 at 2:47 AM Jakub Wartak
<jakub.wartak@enterprisedb.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.
What I think is bound to happen is that some users will not get a
message when one is expected (e.g. the number of connections is very
high but the computer handles it efficiently and so CPU usage remains
low) and others will get one when it's not expected (e.g. the
postmaster is slow because it get stuck reading or writing from the
disk or network, not because of a high connection rate).

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.

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.

--
Robert Haas
EDB: http://www.enterprisedb.com

On Tue, Jul 28, 2026 at 4:00 PM Robert Haas <robertmhaas@gmail.com> wrote:

On Mon, Jul 27, 2026 at 2:47 AM Jakub Wartak
<jakub.wartak@enterprisedb.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]/messages/by-id/CAFbpF8OA44_UG+RYJcWH9WjF7E3GA6gka3gvH6nsrSnEe9H0NA@mail.gmail.com 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]: /messages/by-id/CAFbpF8OA44_UG+RYJcWH9WjF7E3GA6gka3gvH6nsrSnEe9H0NA@mail.gmail.com