Re: Avoid building stderr message if possible

Hi ChangAo, hi Chao Li,

I am reviewing this patch as part of the September patch review workshop,
together with Pooja Gadige and Adi Gollamudi.

== What I checked ==

v1 applies cleanly on master 412ef97d925 and builds without new warnings
(Debian bookworm, gcc 12.2, meson, -Dcassert=true -Ddebug=true). It still
applies cleanly on today's master, c1c5d28f4a2; elog.c has not changed in
between, so everything below still holds.

I built two trees from that same commit, one clean and one patched, and ran
the same script against both: errors carrying DETAIL, HINT and CONTEXT, a
unique violation, a PL/pgSQL exception, and a 400 kB statement, with
log_min_duration_statement = 0. That under five configurations:

log_destination = 'stderr'
log_destination = 'csvlog' with logging_collector = on
log_destination = 'jsonlog' with logging_collector = on
log_destination = 'csvlog,stderr'
log_destination = 'csvlog' with logging_collector = off (the
fallback_to_stderr path)

After masking what differs between any two runs -- timestamps, pids, session
ids, transaction ids, durations, and the location column, which moves
because the patch shifts line numbers in elog.c -- the output is identical
in every case, in every file. So I could not find a behaviour change.

I could not exercise log_destination = 'syslog': there is no syslogd in the
container I build in, so write_syslog() output cannot be captured. That path
is covered by reading the code (elog.c:3778 builds the buffer before calling
write_syslog) and by the experiment below.

== The idea ==

I confirmed the premise, because it is the thing the whole patch rests on:
write_csvlog() (csvlog.c:63) and write_jsonlog() (jsonlog.c:109) each build
their own StringInfo (csvlog.c:87 and jsonlog.c:134) and never read the
buffer that send_message_to_server_log() builds at the top. So with
log_destination = 'csvlog' or 'jsonlog' alone, that buffer really is built
in full and thrown away. The patch is attacking something real.

== What looks right ==

All four consumers of buf are covered: syslog (elog.c:3778), eventlog
(3820), the stderr block (~3860) and the syslogger_setup_done path (3888). I
went through them one at a time: none of them reads buf.data without
build_stderr_message() having run first, and the final pfree is guarded as
well. I could not find a path that reads an uninitialized buf.

There is also no cost in the default configuration: with log_destination =
'stderr' the patch adds one boolean test.

== One thing I checked that could have been a problem, and is not ==

Deferring the build changes which destination computes formatted_log_time
first. On master, log_line_prefix() does it at the very top (the '%m' case
at elog.c:3446 even forces a reset); with the patch and log_destination =
'csvlog,stderr', write_csvlog() now gets there first.

The value does not change: saved_timeval is captured once per message and
reset only in EmitErrorReport (elog.c:1897), before any destination runs.
The comment sitting there says that reset is meant to cover "all the log
destinations". So the csv timestamp and the stderr timestamp stay identical
either way.

Mentioning it only so that nobody else has to re-derive it.

== Confirming the buffer really is skipped ==

Identical output is what a working patch looks like, so it does not by
itself show the buffer is being skipped. There is a way to see it without a
debugger.

log_line_prefix() is called only from inside the block this patch moves into
build_stderr_message() (elog.c:3682-3770), and it increments the static
counter behind '%l'. So: with log_line_prefix = 'LINE=%l ' and
log_destination = 'csvlog', log five errors in one session, then switch that
same session to 'stderr' with ALTER SYSTEM plus pg_reload_conf(), and log
one more.

unpatched: LINE=11 ERROR: division by zero
patched: LINE=1 ERROR: division by zero

So the patch does what it says.

== A side effect of that, which may be worth a line in the commit message ==

The same experiment shows that '%l' now counts only the messages for which
the stderr format was actually rendered, instead of every message logged.
csvlog and jsonlog are not affected, because they keep their own counters
(csvlog.c:69, jsonlog.c:116).

It is narrow: it is only visible if log_destination changes at run time from
a configuration that consumes the buffer to one that does not, or the
reverse. And it is arguable that the new behaviour is the more sensible one,
since a csvlog-only server currently burns line numbers nobody ever sees.
But it is a user-visible difference in something documented as "number of
the log line for each session or process, starting at 1", and I do not think
it was intended. Was it considered?

== Main comment: the lazy build is repeated four times ==

Today initStringInfo(&buf) is at the top of the function (elog.c:3680), so
it is structurally impossible for a destination to read an uninitialized
buf. The patch leaves buf uninitialized and repeats

if (!has_stderr_message)
{
build_stderr_message(&buf, edata);
has_stderr_message = true;
}

at each of the four consumption sites. Whoever adds the next destination
that consumes buf has to remember to repeat it, and if they do not, this
will not fail as a clean NULL dereference: it will read stack garbage, in
the error reporting path, which is where we are least able to afford it.

So the patch is correct today, but it trades an invariant that could not be
broken for one that has to be remembered. Two possible shapes, and I do not
have a strong preference:

(a) a small helper that returns the built buffer and owns the flag, so that
it cannot be skipped;

(b) computing the predicate once, up front. fallback_to_stderr comes from
(Log_destination & (CSVLOG|JSONLOG)) and
!(redirection_done || syslogger_setup_done) (elog.c:3834 and 3848), and
all of those are known before we start, so the decision can be made in
one place. The cost is duplicating the condition.

== Test coverage ==

grep -rln 'csvlog\|jsonlog' src/test/ contrib/

returns nothing. There is no test in the tree that exercises csvlog or
jsonlog at all. The regression suite runs with the default log_destination =
'stderr', which is exactly the path this patch does not change.

That means a green CI run tells us the old path still works, and nothing
about the new one. It is not a fault of this patch, but it does mean the
patch cannot be validated by CI, and it makes a TAP test that starts a
cluster with log_destination = 'csvlog' and compares the output worth having
-- either alongside this patch or separately. I would be glad to help with
that.

== On the benchmark ==

The measurement uses a 32 MB statement with log_min_duration_statement = 0,
so most of what is being saved is copying debug_query_string in the
STATEMENT block (elog.c:3768, via append_with_tabs). With ordinary statement
sizes the saving should be much smaller. Would you be able to post a second
number with a realistic statement size?

To be clear, I do not think the configuration is artificial: csvlog or
jsonlog as the only destination, with log_min_duration_statement = 0, is
what a lot of production installations run, in particular anyone feeding
pgbadger. It is the 32 MB that is extreme, not the setup.

== Naming ==

> I'm not sure why you use "stderr" in the new function name
> build_stderr_message() and the variable name has_stderr_message, as the
> buffer is also consumed by syslog and eventlog. Maybe build_log_buffer()
> and buf_built?

Agreed, for the same reason. One more spot if you do rename: the comment
above the now-conditional pfree still reads

/* No more need of the message formatted for stderr */

and should follow whatever the function ends up being called.

Very minor: the patch also drops a blank line above the
send_message_to_server_log() comment, which just adds noise to the diff.

Thanks for working on this.

--
Diego