[Bucardo-general] Long, predictable delay in synchronization

Paul Theodoropoulos paul at anastrophe.com
Thu Sep 26 21:38:06 UTC 2013


I'm back again. I've been stress testing my bucardo setup, and it's been 
going well, but there is one problem - the speed with which updates on 
one master propogate to the other server.

I have a 'local' master which is where bucardo runs, and a remote 
master. They're on opposite sides of the U.S., but the latency is 
typically under 80ms.. My logfile - even on verbose - only updates about 
once every thirty seconds, and this appears to be the interval with 
which bucardo wakes up.  When I generate a 'bunch' of updates in a loop, 
on either the local or remote master, they seem to be pushed across the 
connection in chunks, in those 30 second intervals. Here's some tiny 
snippets from the logs - the mass of repeating lines (which don't have 
datestamps) happen every 30 seconds, then followed by the log lines of 
the actual activity. I started the loop 14:23:00, and it ran for about 
ten seconds:

NOTICE:  Rows deleted from delta_public_group_stats_main_history_10: 0 
Rows deleted from track_public_group_stats_main_history_10: 0
NOTICE:  Rows deleted from delta_public_group_stats_main_history_56: 0 
Rows deleted from track_public_group_stats_main_history_56: 0
(15399) [Thu Sep 26 14:23:25 2013] KID Delta count for 
local_trumgr_group.public.unit_stats_0                     : 1
(15399) [Thu Sep 26 14:23:25 2013] KID Delta count for 
local_trumgr_group.public.unit_stats_1                     : 1
(etc)
(15399) [Thu Sep 26 14:23:25 2013] KID Delta count for 
local_trumgr_group.public.unit_stats_93                    : 1
(15399) [Thu Sep 26 14:23:33 2013] KID Totals: deletes=25 inserts=25 
conflicts=0
NOTICE:  Rows deleted from delta_public_units_tracking: 0 Rows deleted 
from track_public_units_tracking: 0
NOTICE:  Rows deleted from delta_public_unit_history_14: 0 Rows deleted 
from track_public_unit_history_14: 0
(etc)
NOTICE:  Rows deleted from delta_public_group_stats_main_history_10: 0 
Rows deleted from track_public_group_stats_main_history_10: 0
NOTICE:  Rows deleted from delta_public_group_stats_main_history_56: 0 
Rows deleted from track_public_group_stats_main_history_56: 0
(15399) [Thu Sep 26 14:23:59 2013] KID Delta count for 
local_trumgr_group.public.int_unit_moves                   : 202
(15399) [Thu Sep 26 14:23:59 2013] KID Delta count for 
local_trumgr_group.public.unit_stats_0                     :   3
(etc)
(15399) [Thu Sep 26 14:23:59 2013] KID Delta count for 
local_trumgr_group.public.unit_stats_99                    :   2
(15399) [Thu Sep 26 14:23:59 2013] KID Delta count for 
local_trumgr_group.public.units                            : 202
NOTICE:  Rows deleted from delta_public_units_tracking: 0 Rows deleted 
from track_public_units_tracking: 0
NOTICE:  Rows deleted from delta_public_unit_history_14: 0 Rows deleted 
from track_public_unit_history_14: 0
(etc)
NOTICE:  Rows deleted from delta_public_group_stats_main_history_10: 0 
Rows deleted from track_public_group_stats_main_history_10: 0
NOTICE:  Rows deleted from delta_public_group_stats_main_history_56: 0 
Rows deleted from track_public_group_stats_main_history_56: 0
(15399) [Thu Sep 26 14:24:31 2013] KID Totals: deletes=379 inserts=606 
conflicts=0

As you can see, it took a minute and a half for the other master to 
reflect the entire set of changes. This particular loop was about 1300 
assorted DELETEs, SELECTs, UPDATES, etc

None of my bucardo configs are set to 30 seconds:

postgres at MIA-BUCARDO-tru-main-dev: ~ $ bucardo show all
autosync_ddl              = newcol
bucardo_current_version   = 5.0.0
bucardo_vac               = 1
bucardo_version           = 5.0.0
ctl_checkonkids_time      = 10
ctl_createkid_time        = 0.5
ctl_sleep                 = 0.2
default_conflict_strategy = bucardo_latest
default_email_from        = bucardo at anastrophe.com
default_email_host        = localhost
default_email_to          = sysadmin at anastrophe.com
email_debug_file          =
endsync_sleep             = 1.0
flatfile_dir              = .
host_safety_check         =
isolation_level           = read uncommitted
kid_deadlock_sleep        = 0.5
kid_nodeltarows_sleep     = 0.5
kid_pingtime              = 5
kid_restart_sleep         = 1
kid_serial_sleep          = 0.5
kid_sleep                 = 0.5
log_conflict_file         = /var/log/bucardo/conflict.log
log_level                 = debug
log_microsecond           = 0
log_showlevel             = 0
log_showline              = 0
log_showpid               = 1
log_showtime              = 3
mcp_dbproblem_sleep       = 0.5
mcp_loop_sleep            = 0.2
mcp_pingtime              = 5
mcp_vactime               = 10
piddir                    = /var/run/bucardo
reason_file               = /var/log/bucardo/restart.reason.txt
semaphore_table           = bucardo_status
statement_chunk_size      = 1000
stats_script_url          = http://www.bucardo.org/
stopfile                  = /var/log/bucardo/fullstopbucardo
syslog_facility           = local6
tcp_keepalives_count      = 0
tcp_keepalives_idle       = 0
tcp_keepalives_interval   = 0
vac_run                   = 5
vac_sleep                 = 15
warning_file              = /var/log/bucardo/warning.log

What secret sauce am I missing?

-- 
Paul Theodoropoulos
www.anastrophe.com

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.endcrypt.com/pipermail/bucardo-general/attachments/20130926/0a48dafe/attachment.html>


More information about the Bucardo-general mailing list