Re: log_postmaster_stats

On Mon, Jul 20, 2026 at 3:16 PM Robert Haas <robertmhaas(at)gmail(dot)com> wrote:
>
> On Wed, Jun 10, 2026 at 3:24 AM Jakub Wartak
> <jakub(dot)wartak(at)enterprisedb(dot)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]

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] -
https://www.postgresql.org/message-id/flat/a5916f83-de79-4a40-933a-fb0d9ba2f5a0%40app.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)