On Wed, 23 Sept 2026 at 01:04, Merlin Moncure <[email protected]> wrote: > > While performance testing some epoll style functionality for dblink (see > here: > https://www.postgresql.org/message-id/CAHyXU0w92SrpQtKca9dq%3DYEod44XbKWCoQuANN15C0svPLYhzw%40mail.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
v1-0001-Don-t-log-local-statement-and-context-with-remote.patch
Description: Binary data
