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.
Why do we care about this? Well, it's very easy to issue dblinks that generate a huge amount of side channel traffic, for example, by having a large procedure that raises many notices; these sneaky context messages can consume significant bandwidth and pad the database log. Having to adjust client_min_messages to mitigate is a very awkward and non-obvious trick. A note in the docs about this might be helpful IMO.
merlin
