Barman: rsync wal archival stalls on some files

I’m archiving wal files from a postgres server via rsync, most of the time the archiving works fine and is quick, the speedtest for the connection is here: (this goes via the internet)

[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  9.30 MBytes  78.0 Mbits/sec    0    395 KBytes
[  4]   1.00-2.00   sec  66.3 MBytes   556 Mbits/sec   14   1.05 MBytes
[  4]   2.00-3.00   sec  75.0 MBytes   629 Mbits/sec    0   1.16 MBytes
[  4]   3.00-4.00   sec  81.2 MBytes   682 Mbits/sec    0   1.24 MBytes
[  4]   4.00-5.00   sec  86.2 MBytes   724 Mbits/sec    0   1.30 MBytes
[  4]   5.00-6.00   sec  88.8 MBytes   744 Mbits/sec    0   1.34 MBytes
[  4]   6.00-7.00   sec  91.2 MBytes   765 Mbits/sec    0   1.37 MBytes
[  4]   7.00-8.00   sec  92.5 MBytes   776 Mbits/sec    0   1.38 MBytes
[  4]   8.00-9.00   sec  93.8 MBytes   786 Mbits/sec    0   1.39 MBytes
[  4]   9.00-10.00  sec  63.8 MBytes   535 Mbits/sec   22    535 KBytes

So, more than enough bandwidth available.

But on some WAL files it just crawls to a slow and it takes 30 – 50 seconds until the 16 MB file is transferred, and I’m at a loss where to debug / look for the issue.

The rsync command looks like this:

rsync -p --chmod=Fg+r,Fo+r --timeout 10 -e /usr/bin/ssh -i /var/lib/pgsql/.ssh/id_rsa -a pg_wal/000000080000A5500000005D barman@barman_host/data/database/pg/incoming/000000080000A5500000005D

I looked at rsync via strace on the receiving side, and it seems that just the packets from the sending side were not arriving fast enough.
I tried to cat the file via ssh and output it on my console, that was finished before the rsync transfer.
I tried to cat it to /dev/null, that was instant.

So I assume the source drive is fast enough.

I transferred a bulk of WAL files (60GB) via a single rsync command, that was also quick and averaged 65 MB/s, so that would tell me that everything works fine, still some files are slow.

What else can I look at?
How can I figure out if the issue is sending side, internet speed, receiving side, are there some special logs I can activate on rsync?
Can I check the timings of the syscalls via strace?

ls -l 000000080000A578000000E8
-rw-------. 1 postgres postgres 16777216 Jul 19 07:32 000000080000A578000000E8
bash-4.2$ du -sh 000000080000A578000000E8
11M 000000080000A578000000E8
bash-4.2$ du -sh 000000080000A578000000E8 --apparent-size
16M 000000080000A578000000E8

WAL drive is a ZFS with compression active, therefore the difference.

Also for completion, all zfs properties:

storage/database  type                  filesystem                       -
storage/database  creation              Thu Apr 19 12:22 2018            -
storage/database  used                  1.33T                            -
storage/database  available             369G                             -
storage/database  referenced            1.33T                            -
storage/database  compressratio         2.13x                            -
storage/database  mounted               yes                              -
storage/database  quota                 none                             default
storage/database  reservation           none                             default
storage/database  recordsize            16K                              inherited from storage
storage/database  mountpoint            /data/                        
local
storage/database  sharenfs              off                              default
storage/database  checksum              on                               default
storage/database  compression           lz4                              inherited from storage
storage/database  atime                 off                              inherited from storage
storage/database  devices               on                               default
storage/database  exec                  on                               default
storage/database  setuid                on                               default
storage/database  readonly              off                              default
storage/database  zoned                 off                              default
storage/database  snapdir               hidden                           default
storage/database  aclinherit            restricted                       default
storage/database  createtxg             1159021                          -
storage/database  canmount              on                               default
storage/database  xattr                 sa                               inherited from storage
storage/database  copies                1                                default
storage/database  version               5                                -
storage/database  utf8only              off                              -
storage/database  normalization         none                             -
storage/database  casesensitivity       sensitive                        -
storage/database  vscan                 off                              default
storage/database  nbmand                off                              default
storage/database  sharesmb              off                              default
storage/database  refquota              none                             default
storage/database  refreservation        none                             default
storage/database  guid                  8214081110063784152              -
storage/database  primarycache          all                              default
storage/database  secondarycache        all                              default
storage/database  usedbysnapshots       0B                               -
storage/database  usedbydataset         1.33T                            -
storage/database  usedbychildren        0B                               -
storage/database  usedbyrefreservation  0B                               -
storage/database  logbias               throughput                       inherited from storage
storage/database  dedup                 off                              default
storage/database  mlslabel              none                             default
storage/database  sync                  disabled                         local
storage/database  dnodesize             legacy                           default
storage/database  refcompressratio      2.13x                            -
storage/database  written               1.33T                            -
storage/database  logicalused           2.82T                            -
storage/database  logicalreferenced     2.82T                            -
storage/database  volmode               default                          default
storage/database  filesystem_limit      none                             default
storage/database  snapshot_limit        none                             default
storage/database  filesystem_count      none                             default
storage/database  snapshot_count        none                             default
storage/database  snapdev               hidden                           default
storage/database  acltype               off                              default
storage/database  context               none                             default
storage/database  fscontext             none                             default
storage/database  defcontext            none                             default
storage/database  rootcontext           none                             default
storage/database  relatime              off                              default
storage/database  redundant_metadata    all                              default
storage/database  overlay               off                              default

But nothing was changed in the past days on the ZFS drive – and this whole issue just started on Friday (17th July).

Also, if I copy paste the command, and run it again, it finishes instantly – the still running command will continue to hang.

With ls -lah you can follow how the temporary file gets bigger and bigger (around 150 KB/s)

Thanks for anyone taking time to read this!

Edit: I added timing recording to the wal archive process, here’s the result:

000000080000A57C00000034 1
000000080000A57C00000035 0
000000080000A57C00000036 0
000000080000A57C00000037 1
000000080000A57C00000038 1
000000080000A57C00000039 119
000000080000A57C0000003A 2
000000080000A57C0000003B 1
000000080000A57C0000003C 127
000000080000A57C0000003D 2
000000080000A57C0000003E 1
000000080000A57C0000003F 1
000000080000A57C00000040 1
000000080000A57C00000041 1
000000080000A57C00000042 1
000000080000A57C00000043 1
000000080000A57C00000044 1
000000080000A57C00000045 1
000000080000A57C00000046 1
000000080000A57C00000047 1
000000080000A57C00000048 1
000000080000A57C00000049 105
000000080000A57C0000004A 2
000000080000A57C0000004B 2
000000080000A57C0000004C 1
000000080000A57C0000004D 1
000000080000A57C0000004E 118
000000080000A57C0000004F 2
000000080000A57C00000050 1
000000080000A57C00000051 120
000000080000A57C00000052 2
000000080000A57C00000053 1

The number on the right is seconds it took to execute the Rsync command for the specified file.

Edit 2:

I have recreated the issue with 2 ram drives on each side. I extracted the ports used and have found they are all even (might be a hint)

I have switched between internet connections on my side (target) and the problem went away. Based on discussions it seems to be a network issue over a certain path (maybe due to Load Balancing)

I will update with the final resolution.

Edit 3:

Our provider is Hetzner, they had a fault in one of their DECIX modules (https://www.hetzner-status.de/#16045). After the deactivation the issue went away.