Re: Add wait events for server logging destination writes

Hi Andres, Andrey,

> You're not waiting
> for something while waiting for something else.

Agreed for what is reported: one slot, one wait at a time. The
question is what the slot holds when an inner wait ends.

A server process mostly waits idle (ClientRead, Activity
*_MAIN). When woken it runs with no wait event (NULL), and while
running it may wait on something else (a lock, I/O, a log write).
Core codes these waits one after another, each with its own
start()/end(), so end() writing 0 is correct there.

The trouble comes only when something runs inside an open wait,
between start() and end(). The inner end() then writes 0 while
the outer wait is still going on. Nikolay's harness (Nov 4) hit
this: with v8 the extension's own wait was gone after
ereport(LOG); with v9 it stayed.

I measured two such cases with the attached patches on master
(1fe0cfddf0e; line numbers below refer to it). They are for
measurement only, not a proposal. "restore" is a build where
end() puts back what start() saw. In the flat loops
(ClientRead, WalWriterMain) the two builds look the same.

1. CHECK_FOR_INTERRUPTS() logs, and the log hook waits

The hook is a test extension, but it does what pg_logfebe
does in the field: it ships each message from emit_log_hook
and waits on it.

start(InjectionPoint)
CHECK_FOR_INTERRUPTS() -> ereport(LOG) -> emit_log_hook
start(hook's wait) ... end()
... still waiting for the injection point ...
end()

After the hook, master shows 0 for the remaining 2.2 s;
restore shows InjectionPoint.

2. client_connection_check_interval fires during the wait

start(InjectionPoint)
CHECK_FOR_INTERRUPTS() -> pq_check_connection()
WaitEventSetWait(..., 0): start(0) ... end()
... still waiting for the injection point ...
end()

After each check, master shows 0 and restore shows
InjectionPoint, 62 of 62 times.

In case 2 core itself calls start(0), marking a short stretch of
activity inside the outer wait. With restore, end() then brings
the outer wait back.

Injection points are test infrastructure, but core has the same
shape: proc_exit() inside WaitEventSetWait() on postmaster death
(waiteventset.c:1264), and error context callbacks (elog.c:525)
and emit_log_hook (elog.c:1927) inside I/O waits, e.g. a failed
COPY TO write (copyto.c:651).

Monitoring reads a NULL wait_event as "on CPU". So once end()
writes 0, a process that is still waiting is counted as running.

Nesting thus already happens in core, and hooks called inside a
wait run extension code there. Core cannot control that alone.

> If there are places where
> wait events clear an exising wait event, that code needs to be
> fixed.

Fixed against what? Today the only contract is "end() writes 0",
which cannot tell whether the inner wait or the outer window is
at fault.

This thread adds waits on log writes (Jakub's stuck remote
syslog, Andrey's slow disk). ereport() can be called anywhere, so
every ereport() inside a wait becomes such a place.

Other code that runs inside waits is outside core's control:
emit_log_hook (pg_logfebe does a blocking send() there), error
context callbacks and exit callbacks. contrib/pg_prewarm's worker
waits with WL_EXIT_ON_PM_DEATH (autoprewarm.c:243), and its
before_shmem_exit callback takes an LWLock (autoprewarm.c:905).
On exit 0 is the right value, but today the slot gets it only when
some end() happens to overwrite it, not by a rule.

Fixing only the places in core found to nest, as the swap does,
cannot cover these. They would need a contract of their own:
when called inside a wait, do not start another. Nothing states
or checks that today.

A nesting count could keep the outer wait instead: a start()
inside a window leaves the slot as it is. But it cannot handle
start(0), as in case 2, where core marks a short stretch of
activity inside the outer wait.

> Wait events are for reporting waits, not profiling, not general
> event tracing or whatnot.

Agreed. It stays one slot, with no stack and no history, and it
cannot serve phase tracing: the outer value would show between
sibling phases (parse, plan, execute), and any real wait would
hide the phase. If phases were reported this way:

start(Query) slot
start(Parse) ... end() Parse, then Query again
start(Plan) Plan
start(Lock) ... end() Lock hides Plan, then Plan
end() Query again
start(Execute) ... end() Execute, then Query again
end() 0

Query shows between every two phases, so a sampler cannot tell
"between phases" from "in Query but in no phase".

PostgreSQL does not use threads, but a background thread in a
daemon commonly looks like this, and start()/end() fit the same
shape. pthread_cond_timedwait() gives up the mutex for the wait
and holds it again on return; end() likewise puts back what
start() saw:

start(BlockIdle); slot m
pthread_mutex_lock(&m); BlockIdle held
for (;;)
{
pthread_cond_timedwait(&c, &m, &ts); BlockIdle released,
then held
start(0); 0 held
... work ...
start(DataFileRead) ... end() DataFileRead, then 0
end(); BlockIdle held
}
end();

Code calling start()/end() sees only its own part of the process.
Writing 0 assumes its caller was not waiting; putting back what
start() saw does not need to know, just as above. In PG terms
the contract is three lines:

1. start() and end() pair in one block of one function, like
PG_TRY()/PG_END_TRY(); end() puts back what start() saw.
2. The value saved before sigsetjmp() is put back on ERROR and
when leaving the block, as PG_TRY() already does for
error_context_stack.
3. Switching the storage between the local variable and PGPROC
carries the value over, as SwitchToSharedLatch() does.

Each line is a save/restore pair, and the pairs nest. Errors and
exits still break the inner pairs; the nearest outer pair then
puts its own value back (proc_exit() puts back 0), so nothing is
left half restored. The code is then fixed against the contract:
no pgstat_report_wait_end() used as a reset, and no clear in
AbortSubTransaction() that would wipe what PG_CATCH() put back.

Those patches were for the measurements, not a proposal here.
SeongJun's v10 covers the logging sites with the swap; whether
that is enough for 6819 is for the committers to judge.

The cases above predate this thread, and I see two consistent
answers: forbid nesting by a documented rule, enforced with an
Assert on a start() inside an open wait, or allow it under a new
contract. Today it is neither: nesting happens in core and in
extensions, and end() clears it to 0. Which would you prefer?

Best regards,
Henson