Re: Add wait events for server logging destination writes

Hi,

On 2026-11-14 11:09:11 +0900, Henson Choi wrote:
> 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.

For both of these:

Doing a CFI() while a wait event is set up is bogus. A CFI can execute
arbitrary code. It is not a wait. That's the problem, not that wait events
don't support nesting.

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

There's hardly a need to reset outer wait events in that case, no?

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

Not execute code that can start wait wait events while having a wait event set
up, at least if the outer wait can continue after.

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

No, ereport() cannot be called anywhere. For one, you can't do it with
spinlocks held. But I would also say that it is nonsensical to do it with a
wait event set up.

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

I would prefer not getting way too long LLM generated text blocks.

Greetings,

Andres Freund