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
