Re: Add wait events for server logging destination writes

> 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
>

Hi Nik,

Thanks for running this on all three platforms.

EventlogWrite is the one I'm happiest to see. It's Windows-only
(ReportEventW/A), so until now I could only confirm it compiles. Seeing
it in pg_stat_activity -- 20091 samples, with the job set to fail if
it's never sampled -- is the runtime check the thread was missing, and
it closes the last open item.

Agreed on the WriteConsoleW caveat. I've written the coverage into the
commit messages rather than leave it implicit: SysloggerWrite,
StderrWrite and SyslogWrite sampled at runtime on Linux and macOS, and
EventlogWrite confirmed on Windows via your CI run; WriteConsoleW is
covered by build and review only, since it needs a real console. Your
results are credited there. (And +1 on the NULL share -- it's small
on fast debug builds and grows once the log device is the bottleneck,
which is the case the patch is for.)

Good catch on openlog(). With LOG_NDELAY the socket is connected on the
first log in each process, so it can block the same way the syslog()
calls can; wrapping those but not this felt inconsistent. v6 wraps it,
reusing SyslogWrite since it's the same write_syslog() routine.

That openlog() wrap is the only functional change from v5; otherwise v6
is a rebase plus the commit-message note. I checked it by:

- git am of both patches onto current master (5174d157a03), clean;
- full Meson build (cassert, debug) -- no warnings;
- regression and isolation suites green (245 and 130 tests).

v6-0001 - portable part (SysloggerWrite, StderrWrite, SyslogWrite, now
including the openlog() call)
v6-0002 - Windows part (WriteConsoleW plus EventlogWrite)

Henson, the only change since your v5 review is the openlog() wrap
above. Final comments from anyone are welcome.

Thanks again for the testing and the review.

Seongjun