Re[5]: LISTEN/NOTIFY ultra slow speed

From: Арсен Арутюнян <arutar(at)bk(dot)ru>
To: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Cc: pgsql-general <pgsql-general(at)postgresql(dot)org>
Subject: Re[5]: LISTEN/NOTIFY ultra slow speed
Date: 2022-03-17 18:34:55
Message-ID: 1647542095.577013358@f474.i.mail.ru
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general


I want to tell you about the problem solution. I had to move to postgres 13.
           As can be seen from the async.c code, since the 13th version, the implementation of the  LISTEN/NOTIFY mechanism has undergone major changes. The transfer of tables and database data from version 10 to version 13 went without problems.
           But there were serious difficulties with launching an application to work with the database. It turned out that since the 12th version there is no longer a pg_attrdef.adsr column and I had to patch and rebuild Qt 5.9.6.

result
 
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
 Время: 3,069 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,490 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,932 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,455 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,572 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
 Время: 2,443 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,145 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,581 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 47,704 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,631 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
 Время: 2,427 мс
rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"49064562"}');
Время: 2,647 мс
 
 
--
Arsen Arutyunyan
 
 
>Вторник, 15 марта 2022, 23:48 +03:00 от Арсен Арутюнян <arutar(at)bk(dot)ru>:

>I decided to rebuild pg 10 first.
>I commented out the lines of code with duplicate checking
>(/src/backend/commands/async.c)

>//    if (AsyncExistsPendingNotify(channel, payload))
>//        return;

>and launched this version of pg into production.
>This was the only way I could figure out if there was a significant difference in speed. And the results turned out to be very interesting, the query speed increased  by about two times. But unfortunately it's still far from the desired level

>before the code changes
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 974,119 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 859,855 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 695,741 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 77,001 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 475,590 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 973,449 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 1039,825 мс (00:01,040)
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 1233,576 мс (00:01,234)


>after the code changes
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 431,337 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 460,794 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 498,042 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 604,931 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 438,763 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 587,827 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 621,079 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 549,264 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 447,218 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 526,980 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48119697"}');
>Время: 417,556 мс

>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 185,374 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 554,529 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 654,769 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 577,187 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
>Время: 246,831 мс
>rmdatabase=# select pg_notify('rmdb_client_message','{"Command":239,"MsgId":"48117898"}');
> Время: 648,865 мс

>tomorrow I will deal with the perf

>--
>Arsen Arutyunyan


>>Вторник, 15 марта 2022, 17:32 +03:00 от Tom Lane < tgl(at)sss(dot)pgh(dot)pa(dot)us >:
>> 
>>=?UTF-8?B?0JDRgNGB0LXQvSDQkNGA0YPRgtGO0L3Rj9C9?= < arutar(at)bk(dot)ru > writes:
>>> i looked at the file "\src\backend\commands\async.c"
>>> there is a check for duplicate messages
>>
>>Yup.
>>
>>> Is this slowdown related to this check?
>>
>>[ shrug... ] You've provided no evidence either for or against that
>>possibility.
>>
>>It seems a little unlikely that you could have a lot of pending messages
>>without also seeing data accumulating in pg_notify/, but on the other hand
>>it's also hard to think of other places that time could be getting spent
>>if the queue is always empty. Can you use perf(1) or some such tool to
>>try to identify where the time is being spent? There's some advice
>>about that here:
>>
>>https://wiki.postgresql.org/wiki/Profiling_with_perf
>>
>>> Is it possible to skip the check if I'm absolutely sure the message is unique?
>>
>>Not a good idea. You could upgrade to PG 13 or later, where that
>>code has been improved.
>>
>>regards, tom lane

 

In response to

Browse pgsql-general by date

  From Date Subject
Next Message Zheng Li 2022-03-18 00:18:18 Re: Support logical replication of DDLs
Previous Message Zheng Li 2022-03-17 16:22:46 Re: Support logical replication of DDLs