[Bucardo-general] Bucardo replication delay

Wed Nov 17 22:36:55 UTC 2021

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/20211118/e33b55cc/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/20211118/e33b55cc/attachment-0001.png>