On Thu, Sep 24, 2026 at 2:39 AM vignesh C <[email protected]> wrote:
> On Wed, 23 Sept 2026 at 01:04, Merlin Moncure <[email protected]> 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
