Re: Add wait events for server logging destination writes

On Tue, Jun 30, 2026 at 10:02 AM 신성준 <shinsj4653(at)gmail(dot)com> wrote:

> Hi Henson,
>
> Thanks for the review, and for tracing through
> pgstat_report_wait_start()/end() first -- once the helpers are just a
> single store, placement is the only thing left to check, and thanks for
> going through all four events against their descriptions.
>
> > the comment you plan to add at the wrapped sites in v5 looks right
> > [...] it belongs in a separate change rather than this patch.
>
> Agreed. v5 adds that comment and leaves any general depth-counter
> handling out.
>
> v5 folds in the review:
>
> - a short comment at each wrapped site noting the single-slot
> behavior;
> - Andrey's commit-message point that the real blocking call is
> write_syslogger_file() in the syslogger (no PGPROC, not in
> pg_stat_activity), so the backend-side SysloggerWrite is where the
> stall shows up -- now in the 0001 commit message and a comment on
> write_pipe_chunks().
>
> No functional change from v4.
>
> I'd said I'd hold v5 for platform testing, but since the review has
> landed I'd rather post it than sit on the thread. Testing is still
> welcome, especially the Windows EventlogWrite path -- cfbot confirms it
> builds, but I can't exercise the runtime event-log write here. I'll fold
> anything that turns up into a follow-up.
>
> v5-0001 - portable part (SysloggerWrite, StderrWrite, SyslogWrite)
> v5-0002 - Windows part (WriteConsoleW plus EventlogWrite)
>
> Applies on current master; builds clean under Autoconf and Meson.
>
> Thanks again,
> Seongjun Shin
>

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(at)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(at)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