Up to 50x degradation in dblink performance when receiving notice traffic 19 vs 18

Merlin Moncure <mmoncure@gmail.com> writes:

Bisecting revealed the obvious culprit:
112faf1378ee: Log remote NOTICE, WARNING, and similar messages using
ereport().

The commit solves an obvious problem, and I do not think it should be
reverted. This does raise a couple of questions, however:
* Is it really true that ereport() is up to 20x slower than stderr?
* Why does stderr have such wierd performance variations?

I did a simple performance test, measuring tight loops around

ereport(LOG,
errmsg_internal("%s", my_string));

and

fprintf(stderr, "%s\n", my_string);

For me, ereport is consistently about 3x slower than fprintf
when using bare log-to-a-file (logging_collector off), or about
2x slower when using the logging collector with default options.
That's more or less in line with what I'd expect. So there's
something odd going on in your setup; where is log output going
exactly?

* Why does dblink even bother with NOTICE level messages at all? They are
not produced at all to the receiving client, only to the hosting database
log (which IMO is very non-intuitive).

I think the intent of 112faf137 was to get log message prefixes
attached to these messages without disturbing the pre-existing
behavior about what gets recorded where. Maybe there's room for
a discussion about changing that, but since postgres_fdw has been
acting like that for a long time it might be a hard sell.

regards, tom lane

On Tue, Sep 22, 2026 at 2:31 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

Merlin Moncure <mmoncure@gmail.com> writes:

For me, ereport is consistently about 3x slower than fprintf

when using bare log-to-a-file (logging_collector off), or about
2x slower when using the logging collector with default options.
That's more or less in line with what I'd expect. So there's
something odd going on in your setup; where is log output going
exactly?

Hm, this might be an architecture-specific issue. Try running this
https://pastebin.com/W4snReJh against stock pg18 and pg19 (except for
dblink compiled in). I'm running on a capable Mac laptop. If you
reproduce it, I suspect you might find the pg18 behavior more interesting
(I'm guessing something related to flushed output).

* Why does dblink even bother with NOTICE level messages at all? They

are

not produced at all to the receiving client, only to the hosting database
log (which IMO is very non-intuitive).

I think the intent of 112faf137 was to get log message prefixes
attached to these messages without disturbing the pre-existing
behavior about what gets recorded where. Maybe there's room for
a discussion about changing that, but since postgres_fdw has been
acting like that for a long time it might be a hard sell.

Right... I guess proposing a dblink specific note in the docs that
describes how remote query client messages are composed in the server log,
and the very unintuitive workaround to pass the GUC setting in the
connection string. The existing behavior is perhaps not very good but it
has been in place for quite some time, so I agree.

merlin

On Wed, 23 Sept 2026 at 01:04, Merlin Moncure <mmoncure@gmail.com> wrote:

While performance testing some epoll style functionality for dblink (see here: /messages/by-id/CAHyXU0w92SrpQtKca9dq=YEod44XbKWCoQuANN15C0svPLYhzw@mail.gmail.com if you're curious), I noticed some performance variances in stock dblink I could not explain. The specific test involved:

1. Establish 50 dblink connections to localhost (ssl on/off doesn't matter)
2. Firing async queries through dblink_send_query across 50 connections, where each query generated about 100k of NOTICE traffic.
3. Gather results
4. Loop to step 2, repeat 10x

PG18 behavior (showing loop timings):
NOTICE: LOOP: 1 00:00:00.037583
NOTICE: LOOP: 1 00:00:00.044958
NOTICE: LOOP: 2 00:00:00.03685
NOTICE: LOOP: 3 00:00:00.038189
NOTICE: LOOP: 4 00:00:00.378289
NOTICE: LOOP: 5 00:00:00.038016
NOTICE: LOOP: 6 00:00:00.957476
NOTICE: LOOP: 7 00:00:00.039125
NOTICE: LOOP: 8 00:00:00.926733
NOTICE: LOOP: 9 00:00:00.051012
NOTICE: LOOP: 10 00:00:00.038339

PG19 Behavior (showing loop timings)
NOTICE: LOOP: 1 00:00:02.056779
NOTICE: LOOP: 2 00:00:02.116213
NOTICE: LOOP: 3 00:00:02.10914
NOTICE: LOOP: 4 00:00:02.041574
NOTICE: LOOP: 5 00:00:02.086513
NOTICE: LOOP: 6 00:00:02.116884
NOTICE: LOOP: 7 00:00:02.184659
NOTICE: LOOP: 8 00:00:02.115044
NOTICE: LOOP: 9 00:00:02.114026
NOTICE: LOOP: 10 00:00:02.111078

Notice the time variances for pg18, it vibrates between ~ 40ms and ~1000ms during the gather step. pg19 however, takes around 2x the worst case behavior of pg18. Setting client_min_messages in the remote query to WARNING is very fast in both versions.

Bisecting revealed the obvious culprit:
112faf1378ee: Log remote NOTICE, WARNING, and similar messages using ereport().

The commit solves an obvious problem, and I do not think it should be reverted. This does raise a couple of questions, however:
* Is it really true that ereport() is up to 20x slower than stderr?
* Why does stderr have such wierd performance variations?
* Why does dblink even bother with NOTICE level messages at all? They are not produced at all to the receiving client, only to the hosting database log (which IMO is very non-intuitive).

Anecdotally, I believe I've observed much worse variations in stderr logging in the wild, with multiple minute stall times between ~16k chunks produced to the log. The new behavior, while slower, does seem consistent, which is a plus.

Thanks for the report and the test script. I ran the script unchanged
on 18 and HEAD, with the server log redirected to a file using pg_ctl
-l.
| 18 | HEAD
Loop time | ~34 ms. | ~87 ms
Log bytes/notice. | 1,035 | 3,214
Log lines/notice | 1 | 90

So, I can reproduce the regression. In this test, it is about 2.5x
slower in my environment, and the log is about 3x larger.

The reason becomes clear when looking at a single NOTICE.
On 18:
NOTICE: dblink-one-notice 20260924-114110.923965

On HEAD:
... LOG: received message via remote connection: NOTICE:
dblink-one-notice 20260924-114133.412273
... STATEMENT: SELECT dblink_exec(...);

libpqsrv_notice_receiver() logs each remote message at LOG level. With
defaul log_min_error_statement is set, the full local query is also
logged for every remote message. In this test, that query is about 2
KB, so it gets repeated for all 50,000 notices. When the message is
received inside PL/pgSQL, a CONTEXT line is also added.
Neither the STATEMENT nor CONTEXT lines were intended by commit
112faf1378ee; the intention was only to add the log_line_prefix.

The attached patch fixes this by adding errhidestmt(true) and
errhidecontext(true) to the notice receiver. This makes each remote
message a single log line again.
With the patch:
| 18 | HEAD + patch
Loop time | ~34 ms. | ~52 ms
Log bytes/notice. | 1,035 | 1,116
Log lines/notice | 1 | 1

The remaining ~1.5x is the per-message cost of going through ereport()
instead of a bare fprintf() (running the error context callbacks,
building the log_line_prefix, and so on).

Can you try this and see the difference in your environment?

Regards,
Vignesh

On Thu, Sep 24, 2026 at 2:39 AM vignesh C <vignesh21@gmail.com> wrote:

On Wed, 23 Sept 2026 at 01:04, Merlin Moncure <mmoncure@gmail.com> wrote:

The commit solves an obvious problem, and I do not think it should be

reverted. This does raise a couple of questions, however:

* Is it really true that ereport() is up to 20x slower than stderr?
* Why does stderr have such wierd performance variations?
* Why does dblink even bother with NOTICE level messages at all? They

are not produced at all to the receiving client, only to the hosting
database log (which IMO is very non-intuitive).

Anecdotally, I believe I've observed much worse variations in stderr

logging in the wild, with multiple minute stall times between ~16k chunks
produced to the log. The new behavior, while slower, does seem consistent,
which is a plus.

Thanks for the report and the test script. I ran the script unchanged
on 18 and HEAD, with the server log redirected to a file using pg_ctl
-l.
| 18 | HEAD
Loop time | ~34 ms. | ~87 ms
Log bytes/notice. | 1,035 | 3,214
Log lines/notice | 1 | 90

So, I can reproduce the regression. In this test, it is about 2.5x
slower in my environment, and the log is about 3x larger.

Excellent. First, from a behavior standpoint, your patch gets a double
thumbs up; context pollution in the logs can be a nasty problem.

Applying and testing your patch, my system reverts to v18 timings, which is
also good. Check mark on the patch!

Interestingly, the v18 loop timing variances also remain:

NOTICE: LOOP: 1 00:00:00.044919
<snip>
NOTICE: LOOP: 4 00:00:00.411198
<snip>
NOTICE: LOOP: 6 00:00:00.960661
NOTICE: LOOP: 7 00:00:00.038932
<snip>
NOTICE: LOOP: 10 00:00:00.964332

These are obviously not related to your work. It is worth noting that
with more traffic, timings collapse to the worst case.

For a little more context, I've worked on production outages in dblink
heavy servers where the database process sending the queries experienced
stalls lasting seconds or minutes. I've seen this twice: once on an
on-prem VMWare / SAN fabric and another time on AWS RDS, both linux, with
similar workload but no shared code. Notice traffic was very high due to a
processing loop and context was emitted when the procedure noticed each
entry in the process. Due to production limitations and the inability to
reproduce it locally, I couldn't locate the precise exact point of the
stall.

Looking more deeply I observed:
1. reducing notice traffic fixed the problem, not proportionally, but, kind
of on/off
2. inspecting the log, while the problem was occurring, the stalls seemed
to happen at *exactly* some power of two bytes, 8k/16k, don't recall. Very
suspicious!

Being stubborn to the point of being somewhat obnoxious, I've hunted this
issue for many years. My leading theories involved an SSL buffer problem
or that PostgreSQL receiving so much network traffic through dblink was
causing underlying problems in the O/S. The log timing variances I'm
seeing above seem related but I'm not 100% sure they are the same issue;
however, I'm now doubting both theories (especially SSL).

My work on adding a WaitEventSet based dblink API poll was in part inspired
by attempting to defend against this issue on the premise that sitting
around in poll() and being aggressive with consumeinput vs pg_sleep latch
was somehow more polite to the o/s somehow. Perhaps it's not a bug at all,
but a simple hardware flush problem that postgres is at the mercy of.

merlin

On Thu, Sep 24, 2026 at 8:50 AM Merlin Moncure <mmoncure@gmail.com> wrote:

My work on adding a WaitEventSet based dblink API poll was in part
inspired by attempting to defend against this issue on the premise that
sitting around in poll() and being aggressive with consumeinput vs pg_sleep
latch was somehow more polite to the o/s somehow. Perhaps it's not a bug
at all, but a simple hardware flush problem that postgres is at the mercy
of.

Quick note: turning off logging collector, then disconnecting the session
that invoked pg_ctl so that logs go nowhere, timings go flat and are fast.
So this smells like hardware.

merlin

On Thu, 24 Sept 2026 at 20:21, Merlin Moncure <mmoncure@gmail.com> wrote:

On Thu, Sep 24, 2026 at 2:39 AM vignesh C <vignesh21@gmail.com> wrote:

On Wed, 23 Sept 2026 at 01:04, Merlin Moncure <mmoncure@gmail.com> wrote:

The commit solves an obvious problem, and I do not think it should be reverted. This does raise a couple of questions, however:
* Is it really true that ereport() is up to 20x slower than stderr?
* Why does stderr have such wierd performance variations?
* Why does dblink even bother with NOTICE level messages at all? They are not produced at all to the receiving client, only to the hosting database log (which IMO is very non-intuitive).

Anecdotally, I believe I've observed much worse variations in stderr logging in the wild, with multiple minute stall times between ~16k chunks produced to the log. The new behavior, while slower, does seem consistent, which is a plus.

Thanks for the report and the test script. I ran the script unchanged
on 18 and HEAD, with the server log redirected to a file using pg_ctl
-l.
| 18 | HEAD
Loop time | ~34 ms. | ~87 ms
Log bytes/notice. | 1,035 | 3,214
Log lines/notice | 1 | 90

So, I can reproduce the regression. In this test, it is about 2.5x
slower in my environment, and the log is about 3x larger.

Excellent. First, from a behavior standpoint, your patch gets a double thumbs up; context pollution in the logs can be a nasty problem.

Applying and testing your patch, my system reverts to v18 timings, which is also good. Check mark on the patch!

Thanks for verifying, here is a v2 version updating the commit message
to include Tested-by.
Now that the execution timings are ok, I feel there is no need to
update doc for this, unless you think otherwise.

Interestingly, the v18 loop timing variances also remain:

NOTICE: LOOP: 1 00:00:00.044919
<snip>
NOTICE: LOOP: 4 00:00:00.411198
<snip>
NOTICE: LOOP: 6 00:00:00.960661
NOTICE: LOOP: 7 00:00:00.038932
<snip>
NOTICE: LOOP: 10 00:00:00.964332

These are obviously not related to your work.

I agree this is not related to the changes that we did in
"112faf1378ee: Log remote NOTICE, WARNING, and similar messages using
ereport()."

Regards,
Vignesh

On Fri, Sep 25, 2026 at 1:39 PM vignesh C <vignesh21@gmail.com> wrote:

Thanks for verifying, here is a v2 version

Thanks for the patch!
+1 to calling errhidestmt(true) and errhidecontext(true).

+ /*
+ * Don't log the local statement or context.  This runs once for every
+ * message the remote server sends, and LOG passes the default
+ * log_min_error_statement, so each message would otherwise repeat the
+ * whole text of whatever local query is running.  The local context only
+ * says where libpq happened to be reading input, not what caused the
+ * message.
+ */

This comment sounds a bit redundant and indirect to me. How about a simpler
one like this?

Omit the local statement and context from each remote message.
They can help identify the caller, but repeating them for every
message could greatly increase log volume.

Regards,

--
Fujii Masao

On Fri, 25 Sept 2026 at 10:27, Fujii Masao <masao.fujii@gmail.com> wrote:

On Fri, Sep 25, 2026 at 1:39 PM vignesh C <vignesh21@gmail.com> wrote:

Thanks for verifying, here is a v2 version

Thanks for the patch!
+1 to calling errhidestmt(true) and errhidecontext(true).

+ /*
+ * Don't log the local statement or context.  This runs once for every
+ * message the remote server sends, and LOG passes the default
+ * log_min_error_statement, so each message would otherwise repeat the
+ * whole text of whatever local query is running.  The local context only
+ * says where libpq happened to be reading input, not what caused the
+ * message.
+ */

This comment sounds a bit redundant and indirect to me. How about a simpler
one like this?

Omit the local statement and context from each remote message.
They can help identify the caller, but repeating them for every
message could greatly increase log volume.

Thanks, this looks enough. Here is an updated v3 version patch for the same.

Regards,
Vignesh

On Thu, Sep 24, 2026 at 10:39 PM vignesh C <vignesh21@gmail.com> wrote:

Thanks for verifying, here is a v2 version updating the commit message
to include Tested-by.
Now that the execution timings are ok, I feel there is no need to
update doc for this, unless you think otherwise.

agreed on this point.

merlin

On Fri, Sep 25, 2026 at 11:14 PM Merlin Moncure <mmoncure@gmail.com> wrote:

On Thu, Sep 24, 2026 at 10:39 PM vignesh C <vignesh21@gmail.com> wrote:

Thanks for verifying, here is a v2 version updating the commit message
to include Tested-by.
Now that the execution timings are ok, I feel there is no need to
update doc for this, unless you think otherwise.

agreed on this point.

I've pushed the patch. Thanks!

Regards,

--
Fujii Masao