Re: log_postmaster_stats
Re: log_postmaster_stats
От:
Robert Haas <robertmhaas@gmail.com>
Дата:
On Mon, Jul 27, 2026 at 2:47 AM Jakub Wartak 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
Re: log_postmaster_stats
От:
Robert Haas <robertmhaas@gmail.com>
Дата:
On Wed, Jun 10, 2026 at 3:24 AM Jakub Wartak 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
log_postmaster_stats
От:
Jakub Wartak <jakub.wartak@enterprisedb.com>
Дата:
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.
Known issues include connection storms, spotting low postmaster/fork()
efficency,
PQ workers causing startvation for new connections and so on. It is somehow
complementary to having those pg_stat_database counters mentioned at the
beggining. It is also complementary to the more recent log_connections with
=setup_durations, which logs timings, but not direct rate of forks()/second.
Another interesting thing above is that there can be discrepeancy
between user+system=~5s
against elapsed wall clock time=~10s above (it does not add up) and that's even
getrusage(RUSAGE_SELF and not RUSAGE_CHILDREN), but this comes apparently from
CPU scheduling at those kind of fork() rates. I was thinking about adding some
message like every now and then:
"WARNING: postmaster potentially overloaded, stats not gathered in time"
however lot of folks don't like those self diagnosis messages, so that's not in
v1 patch today.
I've thought it would be good idea to actually to enable it by default (@60s?),
but right now it is off to be aligned with others.
Any hints/reviews are welcome.
-J.
Re: log_postmaster_stats
От:
Jakub Wartak <jakub.wartak@enterprisedb.com>
Дата:
On Mon, Jul 20, 2026 at 3:16 PM Robert Haas wrote:
>
> On Wed, Jun 10, 2026 at 3:24 AM Jakub Wartak
> 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)
Re: log_postmaster_stats
От:
Jakub Wartak <jakub.wartak@enterprisedb.com>
Дата:
On Wed, Jun 10, 2026 at 6:10 AM Quan Zongliang 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.
