Re: Up to 50x degradation in dblink performance when receiving notice traffic 19 vs 18 - Mailing list pgsql-hackers

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:
https://www.postgresql.org/message-id/CAHyXU0w92SrpQtKca9dq%3DYEod44XbKWCoQuANN15C0svPLYhzw%40mail.gmail.comif 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
NOTICEtraffic. 
> 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,
takesaround 2x the worst case behavior of pg18.   Setting client_min_messages in the remote query to WARNING is very
fastin 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
timesbetween ~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