Re: Add wait events for server logging destination writes

The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, passed

Hi Seongjun,

I tested v6. Reading back through the thread, the runtime testing so far has
covered SysloggerWrite, StderrWrite and EventlogWrite, but I could not find a
report of anyone running with log_destination = 'syslog', so SyslogWrite -- and
the openlog() call added in v6 -- looked like the parts still resting on code
reading alone. Those are what I concentrated on.

Scope: I tested the Unix paths in 0001 only. I did not test the Windows paths
in 0002 (EventlogWrite, WriteConsoleW); those still rest on Nikolay's CI run and
on code review.

Environment
-----------
Ubuntu 24.04.4 LTS on aarch64, glibc 2.39, gcc 13.3.0, meson 1.3.2 / ninja
1.11.1, configured with -Dcassert=true -Dbuildtype=debug.

v6-0001 and v6-0002 still apply cleanly to today's master (74276e685dd0), build
with no compiler warnings, and "meson test" is green: 350 passed, 0 failed,
33 skipped. All four events are present in pg_wait_events.

For each scenario below I ran the identical procedure against an unpatched build
of that same commit and took a backtrace of a blocked backend in both, so the
"before" and "after" can be compared at the same call site. Sampling is
pg_stat_activity every ~2ms, tallied over 25-30s, following the method Nikolay
used upthread so the numbers are comparable.

1. syslog(3) -- IO / SyslogWrite
--------------------------------
To make syslog(3) block deterministically I replaced /dev/log with a SOCK_DGRAM
listener that never recv()s (scripts attached). Once its receive buffer fills,
glibc's syslog() blocks in send(2). Server configured with
log_destination = 'syslog', logging_collector = off; load is 8 backends emitting
8kB LOG lines.

write_syslog() has two syslog() call sites, and they are selected by
syslog_split_messages, so I ran it both ways.

syslog_split_messages = on (chunked path, elog.c:2909)
unpatched NULL 81160 samples 100.0%
v6 IO / SyslogWrite 81008 samples 100.0%

syslog_split_messages = off (unchunked path, elog.c:2923)
unpatched NULL 54280 samples 100.0%
v6 IO / SyslogWrite 67416 samples 100.0%

Both builds have the same stack, e.g. for the chunked path:

#0 __libc_send () at ../sysdeps/unix/sysv/linux/send.c:28
#1 __vsyslog_internal () at ./misc/syslog.c:288
#2 __syslog () at ./misc/syslog.c:91
#3 write_syslog (level=6, ...) at ../src/backend/utils/error/elog.c:2909
#4 send_message_to_server_log () at ../src/backend/utils/error/elog.c:3848
#5 EmitErrorReport () at ../src/backend/utils/error/elog.c:1925

With the openlog() case below, that covers all three wrapped call sites in
write_syslog().

2. openlog(3) -- the v6 delta
-----------------------------
To reach the stream-socket fallback you described, I replaced /dev/log with a
SOCK_STREAM listener with a backlog of 0 that never accept()s. openlog() then
tries SOCK_DGRAM, gets EPROTOTYPE, retries with SOCK_STREAM, and blocks in
connect(2) once the single queue slot is taken.

unpatched 6 of 6 probe backends: state = active, wait_event IS NULL
v6 6 of 6 probe backends: IO / SyslogWrite

and in both builds those backends are here:

#0 __libc_connect () at ../sysdeps/unix/sysv/linux/connect.c:26
#1 openlog_internal () at ./misc/syslog.c:357
#2 openlog () at ./misc/syslog.c:386
#3 write_syslog (level=6, ...) at ../src/backend/utils/error/elog.c:2827
#4 send_message_to_server_log () at ../src/backend/utils/error/elog.c:3848
#5 EmitErrorReport () at ../src/backend/utils/error/elog.c:1925

So the openlog() wrapping does what it is meant to do.

Getting there took one step that may be worth reflecting in the commit message:
with fork()-based backends, openlog_done and the syslog fd are inherited from
the postmaster, so a backend does not normally reach openlog() at all -- the
postmaster opens the connection for its own first message and every child
inherits it. The way to reach it in a backend is to change syslog_ident or
syslog_facility and reload, since assign_syslog_facility() does closelog() +
openlog_done = false in every process that applies the reload. (A backend also
only applies a pending reload when it returns to its main loop, not mid-query,
which matters when writing a test for this.) So on Unix the backend-visible
openlog() case is real but narrow, and the postmaster case never appears in
pg_stat_activity anyway. Wrapping it still looks right to me -- it costs
nothing and it is the same routine -- but the current wording reads as though
the call is reached on any first log message in each process.

3. syslogger pipe -- IO / SysloggerWrite
----------------------------------------
Same idea for the case Andrey described. With logging_collector = on I
SIGSTOPed the syslogger so the pipe fills and backends block in the pipe write:

unpatched NULL 91360 samples 100.0%
v6 IO / SysloggerWrite 92992 samples 100.0%

with an identical stack in both (write_pipe_chunks -> __libc_write). This is
the "the node looks CPU-bound but it is really the log device" case, and it is
much starker than the numbers from a healthy log device: 100% of the
active-backend samples are unattributed before the patch.

4. The single-slot masking question
-----------------------------------
Since this was the one open design point, I tried to settle it from the source
rather than by argument. For an outer wait event to be masked, an ereport()
that RETURNS -- LOG, WARNING, NOTICE, INFO, DEBUGn, but not ERROR and above,
which unwind -- has to be reachable between a pgstat_report_wait_start() and its
matching pgstat_report_wait_end(). I scanned src/backend, src/common and
src/port for exactly that (script attached):

files scanned 1022
wait-event regions paired 98
starts the pairing could not resolve 2
regions containing a directly reachable
ereport/elog at a returning level 1

The two unresolved starts are the LWLockReportWaitStart() helper itself, whose
matching end is in a different function, and a mention in a comment header;
neither is a region.

The single hit is in AddToDataDirLockFile():

pgstat_report_wait_start(WAIT_EVENT_LOCK_FILE_ADDTODATADIR_SYNC);
if (pg_fsync(fd) != 0)
ereport(LOG, (errcode_for_file_access(), ...));
pgstat_report_wait_end();

(The pg_pwrite() case just above it calls pgstat_report_wait_end() before its
ereport; the fsync case does not.) Every caller of AddToDataDirLockFile() is in
the postmaster -- postmaster.c and PGSharedMemoryCreate() -- which is exactly
the case Henson carved out: no PGPROC, so my_wait_event_info points at the
process-local dummy and nothing observable changes. Even setting that aside, it
is an fsync-failure path, and the event it would clear is its own, after the
fsync has already returned.

Limitations, so this is not read as more than it is: the scan is lexical and
intra-procedural. It does not follow calls made inside a region, so an
ereport() in a callee would not be found.

As a sanity check I also compared wait-event profiles under a heavy-logging but
healthy-log-device workload (pgbench -c 8 -j 4 for 60s, with
log_min_duration_statement = 0, log_checkpoints = on,
log_autovacuum_min_duration = 0, log_lock_waits = on), three runs per build,
alternating. Share of each run's total:

event unpatched v6
-----------------------------------------------------
NULL 43.4 - 44.1 41.4 - 44.1
LWLock / WALWrite 24.8 - 25.4 23.0 - 25.1
Client / ClientRead 11.5 - 11.9 11.7 - 11.9
IO / WalSync 11.0 - 11.1 10.9 - 11.0
Lock / transactionid 6.3 - 6.6 5.9 - 6.6
IO / SysloggerWrite -- 2.3 - 2.4

Every existing event's range overlaps between the two builds; only the new event
separates them. I would not push this further than that: the total sample count
varied from 149844 to 199272 across runs, so the percentages share a moving
denominator, and this method cannot resolve an effect smaller than the
run-to-run spread of roughly two points. The source scan is the part I would
rely on.

One non-blocking suggestion
---------------------------
Now that openlog() is wrapped with SyslogWrite, this description

SYSLOG_WRITE "Waiting for a write to the system logger (syslog)."

is not quite accurate at that call site: openlog() is establishing the
connection, not writing. The string is user-visible in pg_wait_events and in
the documentation table, and operationally "syslog is slow to accept writes" and
"we cannot connect to the syslog daemon at all" point at different things.

Michael already said upthread that sharing an event within one routine is fine,
so I am not proposing a separate event -- just a wording tweak, if you agree:

SYSLOG_WRITE "Waiting for a write to the system logger (syslog), including connection setup."

Neither this nor the commit-message wording above looks blocking to me; both
could equally be folded in at commit time.

Attached are the scripts I used, in case anyone wants to reproduce these:
blackhole_dgram.py and blackhole_stream.py (the two /dev/log listeners),
devlog_takeover.sh / devlog_restore.sh, sample_wait_events.sql,
run_scenario.sh, run_openlog_scenario.sh, run_masking_check.sh, and
audit_wait_regions.py.

A warning about them: the two listeners replace the host's /dev/log, so any
process on that machine which logs through syslog(3) -- sudo included -- can
block while they are running. Please run them in a throwaway VM or container,
not anywhere you care about.

Nothing here looks blocking to me, so I have marked the entry Ready for
Committer. Henson, Nik -- please move it back if you disagree.

Tested-by: Jihyun Bahn <rring0727(at)gmail(dot)com>

Regards,
Jihyun Bahn