[Bucardo-general] Initial one time copy of a large table, with writes traffic at the source

[Yap Sok Ann]

This is a "Part II" of the thread started by Jeff a couple of months ago, with subject "Syncing a large table".

Like Jeff, we also experienced difficulty when doing the initial one time copy of a large table (1TB), which also has some writes traffic at the source database.

>From our analysis, it looks like while the KID process is busy copying a table, it won't bother to process all the LISTEN/NOTIFY notices sent due to changes at the source db, relayed to the main db via MCP -> CTL -> KID. Eventually, the receiving buffer (Recv-Q) of the connection from KID to main db will be full, and any subsequent notice from main db to KID will then be stuck in the sending buffer (Send-Q) and go into TCP retransmission. After 15 TCP retransmissions (default for "tcp_retries2", see `man 7 tcp`), the kernel will then close the socket and return ETIMEDOUT to main db.

When this happens, the KID process will continue the copying, blissfully unaware that its connection to main db has already been broken.

When the copying of the large table eventually finishes, the KID process will then get error "EOF detected" and die while trying to move to the next table.

For now, we try to workaround this by bumping up the TCP buffer size, i.e.

net.core.rmem_max = 134217728
net.core.wmem_max = 134217728
net.ipv4.tcp_rmem = 4096 87380 134217728
net.ipv4.tcp_wmem = 4096 65536 134217728

This is with bucardo version 5.4.1. Don't have the chance to try 5.5.0 yet.

Below are some sample log lines and ss output to illustrate the issue:

1. Started the initial one time copy:

# bucardo log
(9817) [Thu Sep  5 13:51:13 2019] KID (test_sync) New kid, sync "test_sync" alive=1 Parent=9812 PID=9817 kicked=1 OTC: 2

# `ss -ntop` output related to the connection from KID to main db (both directions)
Thu Sep  5 13:51:14 UTC 2019
ESTAB       0        0               127.0.0.1:41666          127.0.0.1:5432     users:(("Bucardo Kid. Sy",pid=9817,fd=13)) timer:(keepalive,119min,0)
ESTAB       0        0               127.0.0.1:5432           127.0.0.1:41666    users:(("postgres",pid=9818,fd=12)) timer:(keepalive,119min,0)

2. Started to copy the large table:

# bucardo log
(9817) [Thu Sep  5 17:28:53 2019] KID (test_sync) Copying from source_db.public.table1

3. Connection from KID to main db broken in one direction, after 15 TCP retransmissions:

# postgres log of main db
2019-09-05 22:41:59.359 UTC [9818] bucardo at bucardo LOG:  could not receive data from client: Connection timed out
2019-09-05 22:41:59.359 UTC [9818] bucardo at bucardo LOG:  disconnection: session time: 8:50:45.755 user=bucardo database=bucardo host=127.0.0.1 port=41666

# `ss -ntop` output related to the connection from KID to main db (one direction left)
Thu Sep  5 22:41:57 UTC 2019
ESTAB  4935960    0                  127.0.0.1:41666          127.0.0.1:5432     users:(("Bucardo Kid. Sy",pid=9817,fd=13)) timer:(keepalive,71min,0)
ESTAB  0          286320             127.0.0.1:5432           127.0.0.1:41666    users:(("postgres",pid=9818,fd=12)) timer:(on,812ms,15)

Thu Sep 5 22:41:58 UTC 2019
ESTAB  4935960    0                  127.0.0.1:41666          127.0.0.1:5432     users:(("Bucardo Kid. Sy",pid=9817,fd=13)) timer:(keepalive,71min,0)
ESTAB  0          286620             127.0.0.1:5432           127.0.0.1:41666    users:(("postgres",pid=9818,fd=12)) timer:(on,71582min,15)

Thu Sep 5 22:41:59 UTC 2019
ESTAB  4935960    0                  127.0.0.1:41666          127.0.0.1:5432     users:(("Bucardo Kid. Sy",pid=9817,fd=13)) timer:(keepalive,71min,0)

4. Copying of the large table finished, the KID process got error and died while trying to move to the next table:

# bucardo log
(9817) [Fri Sep  6 01:27:03 2019] KID (test_sync) Rows copied to dest_db.public.table1: 3813621472
(9817) [Fri Sep  6 01:27:03 2019] KID (test_sync) Emptying out dest_db.public.table2 using delete
(9817) [Fri Sep  6 01:27:03 2019] KID (test_sync) Kid has died, error is: DBD::Pg::st execute failed: SSL SYSCALL error: EOF detected at /usr/share/perl5/Bucardo.pm line 4625. Line: 5041 Main DB state: 08000 Error: 7 DB dest_db state: ? Error: none DB source_db state: ? Error: none