Re: Up to 50x degradation in dblink performance when receiving notice traffic 19 vs 18

On Thu, 24 Sept 2026 at 20:21, Merlin Moncure <mmoncure(at)gmail(dot)com> wrote:
>
> On Thu, Sep 24, 2026 at 2:39 AM vignesh C <vignesh21(at)gmail(dot)com> wrote:
>>
>> On Wed, 23 Sept 2026 at 01:04, Merlin Moncure <mmoncure(at)gmail(dot)com> 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!

Thanks for verifying, here is a v2 version updating the commit message
to include Tested-by.
Now that the execution timings are ok, I feel there is no need to
update doc for this, unless you think otherwise.

> 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.

I agree this is not related to the changes that we did in
"112faf1378ee: Log remote NOTICE, WARNING, and similar messages using
ereport()."

Regards,
Vignesh