Re: Add wait events for server logging destination writes - Mailing list pgsql-hackers

Hi Seongjun,

(I reviewed and tested v4 back in June but never sent the results;
now doing it for v5.)

I ran runtime tests of this patch set on Linux, macOS, and Windows;
results below. tl;dr: both v5 patches apply cleanly (git am) to
current master (11ed011ae22) and build clean, and all four events
show up in pg_stat_activity under load -- including EventlogWrite on
Windows, which I believe was the one path previously only
build-verified. +1 from me.

** Methodology **

8 backends each run a plpgsql loop of 50k RAISE LOG calls with an
8 kB payload, while a separate connection samples pg_stat_activity
every ~2 ms and tallies wait_event. The driver scripts and the
Windows CI job are public:

https://github.com/NikolayS/postgres/tree/ci/windows-waitevents
workflow: .github/workflows/windows-waitevents.yml

** Results **

Linux (tested June 15 with v4; gcc 13, meson debug; I did not rerun
since the v4->v5 code delta is comment-only):

logging_collector = on  -> IO/SysloggerWrite  3652 (46.3% of all
samples, null wait_event included)
logging_collector = off -> IO/StderrWrite     1376 (17.6%)

macOS (v5 on master@11ed011ae22; clang 17, meson debug):

logging_collector = on  -> IO/SysloggerWrite  47362 samples
(the only wait event observed)
logging_collector = off -> IO/StderrWrite     13710 samples

Windows (v5 on master@11ed011ae22; MSVC/meson, windows-latest,
log_destination = 'stderr,eventlog'):

IO/EventlogWrite  20091 samples
IO/StderrWrite      642 samples

Run: https://github.com/NikolayS/postgres/actions/runs/29425495163
(the job fails hard if EventlogWrite is never sampled; it passed)

Counts are pg_stat_activity rows summed over sampler ticks and
backends, and run lengths differed, so they are not comparable
across platforms.

One caveat on Windows coverage: GitHub Actions redirects stderr, so
the WriteConsoleW branch of write_console() is not truly exercised
there -- the samples above go through the write(fileno(stderr))
branch plus write_eventlog(). I don't see it as blocking -- the
WriteConsoleW wrapping is mechanically identical to its sibling.

The NULL share varies with how fast the log device is: these are
debug builds on fast storage, so backends spend most of their time
formatting on-CPU. On a saturated pipe or a slow log device --
exactly Andrey's network-HDD case -- the attributable share grows,
which is precisely what the patch makes visible.

** Review notes on v5 **

I checked the v4->v5 delta -- comments and commit-message text only
(single-slot masking notes at each wrapped site, and the explanation
that the on-disk write happens in write_syslogger_file() in the
syslogger, which has no PGPROC, so the backend-side SysloggerWrite on
the pipe write is where a stall becomes visible). That addresses the
points from Andrey's and Henson's reviews, thank you.

One optional thought on write_syslog(): openlog() is called with
LOG_NDELAY, so the connection to the syslog socket is opened right
there on the first call in each process, and in principle that can
block too (e.g. glibc's stream-socket fallback with a busy syslog
daemon). That call could also be wrapped with SyslogWrite. It is
once per process, so take it or leave it -- not blocking.

Nik