[Bucardo-general] Bucardo replication delay

Lucas Possamai drum.lucas at gmail.com
Thu Nov 18 21:35:44 UTC 2021 

Hello,

Looks like the fix also fixed the replication delay. All looking good now.

lucas

On Thu, 18 Nov 2021 at 14:31, Lucas Possamai <drum.lucas at gmail.com> wrote:

> Hi,
>
> I found the issue about the high CPU utilization. There was a PostgreSQL
> Bucardo process stuck on the source db. When I stopped Bucardo I noticed
> it. Had to manually kill it with kill -9 but the replication looks fine.
>
> CPU Utilization went back to normal.
> [image: Screen Shot 2021-11-18 at 2.22.58 PM.png]
> Now the only issue is with the replication delay.
> Hopefully someone can help me with that.
>
> Cheers,
> lucas
>
> On Thu, 18 Nov 2021 at 11:36, Lucas Possamai <drum.lucas at gmail.com> wrote:
>
>> Any help here guys, about the high CPU utilization and the replication
>> delay, please? This is causing headaches...
>>
>> Thanks
>> Lucas
>>
>>
>> On Wed, 17 Nov 2021 at 14:06, Lucas Possamai <drum.lucas at gmail.com>
>> wrote:
>>
>>> I also noticed that CPU Utilization increased quite a lot after Bucardo
>>> was enabled two days ago
>>> [image: image.png]
>>> Lucas
>>>
>>> On Wed, 17 Nov 2021 at 09:56, Lucas Possamai <drum.lucas at gmail.com>
>>> wrote:
>>>
>>>> Hi there, thanks for your reply.
>>>>
>>>> The database size is ~ 1.5TB.
>>>>
>>>> *select * from sync;*
>>>> xxx_sync xxx_db_group xxx_db_group true true bucardo_latest delete true
>>>> active 0 0 true false true 00:00:00 00:00:00 false 0 0 2021-11-12
>>>> 18:17:14.068 +1300
>>>>
>>>> *select * from syncrun s order by started desc;*
>>>> xxx_sync 0 0 0 0 2021-11-17 09:51:09.474 +1300 false false false
>>>> delta_check on db source_db
>>>> xxx_sync 0 4471 7001 0 2021-11-17 09:49:04.966 +1300 2021-11-17
>>>> 09:51:09.466 +1300 true false false Complete (KID 514737)
>>>> xxx_sync 0 0 0 0 2021-11-17 09:45:48.005 +1300 2021-11-17 09:47:33.051
>>>> +1300 false true false Ended (CTL 499524)
>>>> xxx_sync 0 2565 4595 0 2021-11-17 09:43:38.295 +1300 2021-11-17
>>>> 09:45:47.998 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1460 2588 0 2021-11-17 09:39:33.227 +1300 2021-11-17
>>>> 09:43:38.287 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 2344 4241 0 2021-11-17 09:37:05.888 +1300 2021-11-17
>>>> 09:39:33.219 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1091 2086 0 2021-11-17 09:34:02.473 +1300 2021-11-17
>>>> 09:37:05.881 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1530 2940 0 2021-11-17 09:31:46.196 +1300 2021-11-17
>>>> 09:34:02.466 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 634 1206 0 2021-11-17 09:28:53.103 +1300 2021-11-17
>>>> 09:31:46.189 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1619 3163 0 2021-11-17 09:27:19.426 +1300 2021-11-17
>>>> 09:28:53.097 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1655 2900 0 2021-11-17 09:24:01.256 +1300 2021-11-17
>>>> 09:27:19.418 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1301 2531 0 2021-11-17 09:21:05.694 +1300 2021-11-17
>>>> 09:24:01.249 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1273 2460 0 2021-11-17 09:18:17.733 +1300 2021-11-17
>>>> 09:21:05.686 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1380 2543 0 2021-11-17 09:14:58.345 +1300 2021-11-17
>>>> 09:18:17.725 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1350 2250 0 2021-11-17 09:11:52.516 +1300 2021-11-17
>>>> 09:14:58.337 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 936 1920 0 2021-11-17 09:09:07.709 +1300 2021-11-17
>>>> 09:11:52.509 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 2856 4393 0 2021-11-17 09:06:07.831 +1300 2021-11-17
>>>> 09:09:07.701 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 7555 9247 0 2021-11-17 09:02:34.485 +1300 2021-11-17
>>>> 09:06:07.823 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 9446 10403 0 2021-11-17 08:58:38.809 +1300 2021-11-17
>>>> 09:02:34.476 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1368 2925 0 2021-11-17 08:55:45.219 +1300 2021-11-17
>>>> 08:58:38.801 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1300 2116 0 2021-11-17 08:52:33.204 +1300 2021-11-17
>>>> 08:55:45.212 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1025 1834 0 2021-11-17 08:50:25.835 +1300 2021-11-17
>>>> 08:52:33.197 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 450 883 0 2021-11-17 08:48:01.674 +1300 2021-11-17
>>>> 08:50:25.829 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1116 1877 0 2021-11-17 08:45:57.384 +1300 2021-11-17
>>>> 08:48:01.668 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1303 2703 0 2021-11-17 08:43:46.317 +1300 2021-11-17
>>>> 08:45:57.377 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1009 1750 0 2021-11-17 08:40:39.570 +1300 2021-11-17
>>>> 08:43:46.309 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1122 1998 0 2021-11-17 08:38:03.735 +1300 2021-11-17
>>>> 08:40:39.563 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1554 2769 0 2021-11-17 08:34:58.085 +1300 2021-11-17
>>>> 08:38:03.728 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 2075 3170 0 2021-11-17 08:31:35.324 +1300 2021-11-17
>>>> 08:34:58.078 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1242 2408 0 2021-11-17 08:28:48.330 +1300 2021-11-17
>>>> 08:31:35.317 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1195 2090 0 2021-11-17 08:26:11.722 +1300 2021-11-17
>>>> 08:28:48.323 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 772 1460 0 2021-11-17 08:23:42.756 +1300 2021-11-17
>>>> 08:26:11.715 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 648 1257 0 2021-11-17 08:20:56.834 +1300 2021-11-17
>>>> 08:23:42.748 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 849 1641 0 2021-11-17 08:18:45.062 +1300 2021-11-17
>>>> 08:20:56.827 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1913 3301 0 2021-11-17 08:16:36.418 +1300 2021-11-17
>>>> 08:18:45.056 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1116 2052 0 2021-11-17 08:11:29.873 +1300 2021-11-17
>>>> 08:16:36.410 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 3375 6197 0 2021-11-17 08:08:32.526 +1300 2021-11-17
>>>> 08:11:29.863 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1584 2776 0 2021-11-17 08:00:24.198 +1300 2021-11-17
>>>> 08:08:32.515 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1963 3699 0 2021-11-17 07:55:29.967 +1300 2021-11-17
>>>> 08:00:24.189 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1600 1464 0 2021-11-17 07:49:14.340 +1300 2021-11-17
>>>> 07:55:29.958 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1024 2319 0 2021-11-17 07:46:39.718 +1300 2021-11-17
>>>> 07:49:14.334 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 884 1417 0 2021-11-17 07:43:06.218 +1300 2021-11-17
>>>> 07:46:39.711 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 555 1073 0 2021-11-17 07:41:16.378 +1300 2021-11-17
>>>> 07:43:06.211 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 669 1050 0 2021-11-17 07:39:22.271 +1300 2021-11-17
>>>> 07:41:16.372 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 358 597 0 2021-11-17 07:37:50.851 +1300 2021-11-17
>>>> 07:39:22.265 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 272 406 0 2021-11-17 07:36:30.132 +1300 2021-11-17
>>>> 07:37:50.845 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 360 689 0 2021-11-17 07:35:12.780 +1300 2021-11-17
>>>> 07:36:30.127 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 258 518 0 2021-11-17 07:33:29.330 +1300 2021-11-17
>>>> 07:35:12.774 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1474 2114 0 2021-11-17 07:31:28.993 +1300 2021-11-17
>>>> 07:33:29.323 +1300 false false false Complete (KID 499526)
>>>> xxx_sync 0 1511 1686 0 2021-11-17 07:29:53.678 +1300 2021-11-17
>>>> 07:31:28.987 +1300 false false false Complete (KID 499526)
>>>>
>>>> Hope that helps. Thanks!
>>>> Lucas
>>>>
>>>> On Wed, 17 Nov 2021 at 01:10, ManuParra <mparra at iaa.es> wrote:
>>>>
>>>>> Hi Lucas, what is the size of the data you are syncing ? I see 211
>>>>> tables in total, and, do you have an estimation of the size you are moving?.
>>>>>
>>>>> I’ve been working on how bucardo scale in different scenarios of data
>>>>> size, as number of registers, tables and size of the syncing.
>>>>>
>>>>> In order to know more in depth I recommend you to check bucado DB
>>>>> tables (psql -U bucardo): sync and syncrun in both bucardo instances and
>>>>> paste here (sorted by started DESC field) the first registers. In syncrun
>>>>> tables you will see the delay and the status of the transaction, etc.
>>>>>
>>>>> Let me know if you have this information.
>>>>>
>>>>> Cheers,
>>>>> Manu.
>>>>>
>>>>>
>>>>> On 16 Nov 2021, at 02:37, Lucas Possamai <drum.lucas at gmail.com> wrote:
>>>>>
>>>>> Hi,
>>>>> I've setup a replication between PG 9.2 and PG 14 for a migration. I
>>>>> noticed that the replication is quite delayed, and was wondering if I
>>>>> missed something, or if it's just the way Bucardo works?
>>>>>
>>>>> Below you can see a screenshot of the same query being run in PG 14
>>>>> via Bucardo (*left*) and PG 9.2 streaming replication slave (*right*):
>>>>> <Screen Shot 2021-11-16 at 2.26.39 PM.png>
>>>>> Notice that Bucardo is quite behind. Is that expected? Can't I improve
>>>>> that somehow?
>>>>>
>>>>> <Screen Shot 2021-11-16 at 2.34.58 PM.png>
>>>>> Bucardo status looks okay.
>>>>>
>>>>>
>>>>> *Some extra information:*
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>
>>>>> master --> slave01 (Postgres 9.2 streaming replication)
>>>>>             --> slave02 (Postgres 9.2 streaming replication)
>>>>>             --> slave03 (Postgres 9.2 streaming replication)
>>>>>             --> slave04 (Postgres 9.2 streaming replication)
>>>>>             --> Bucardo --> PG 14
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>
>>>>> Thanks
>>>>> Lucas
>>>>> _______________________________________________
>>>>> Bucardo-general mailing list
>>>>> Bucardo-general at bucardo.org
>>>>> https://bucardo.org/mailman/listinfo/bucardo-general
>>>>>
>>>>>
>>>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://bucardo.org/pipermail/bucardo-general/attachments/20211119/69b6c5df/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image.png
Type: image/png
Size: 175474 bytes
Desc: not available
URL: <https://bucardo.org/pipermail/bucardo-general/attachments/20211119/69b6c5df/attachment-0002.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Screen Shot 2021-11-18 at 2.22.58 PM.png
Type: image/png
Size: 262990 bytes
Desc: not available
URL: <https://bucardo.org/pipermail/bucardo-general/attachments/20211119/69b6c5df/attachment-0003.png>

More information about the Bucardo-general mailing list