Sync two PBS local/remote

[m0m0]

Hi all,

I know that this topic has been dealt with several times when looking on the forum, but I think I am facing a problem that I have not found.
The following data concerning the thread:

proxmox-backup-client benchmark --repository remoteip:remote
Uploaded 13 chunks in 9 seconds.
Time per request: 768579 microseconds.
TLS speed: 5.46 MB/s
SHA256 speed: 157.98 MB/s
Compression speed: 200.58 MB/s
Decompress speed: 270.11 MB/s
AES256/GCM speed: 67.23 MB/s
Verify speed: 98.09 MB/s
┌───────────────────────────────────┬───────────────────┐
│ Name │ Value │
╞═══════════════════════════════════╪═══════════════════╡
│ TLS (maximal backup upload speed) │ 5.46 MB/s (0%) │
├───────────────────────────────────┼───────────────────┤
│ SHA256 checksum computation speed │ 157.98 MB/s (8%) │
├───────────────────────────────────┼───────────────────┤
│ ZStd level 1 compression speed │ 200.58 MB/s (27%) │
├───────────────────────────────────┼───────────────────┤
│ ZStd level 1 decompression speed │ 270.11 MB/s (23%) │
├───────────────────────────────────┼───────────────────┤
│ Chunk verification speed │ 98.09 MB/s (13%) │
├───────────────────────────────────┼───────────────────┤
│ AES256 GCM encryption speed │ 67.23 MB/s (2%) │
└───────────────────────────────────┴───────────────────┘

proxmox-backup-client benchmark --repository localip:local
Uploaded 13 chunks in 9 seconds.
Time per request: 758928 microseconds.
TLS speed: 5.53 MB/s
SHA256 speed: 94.44 MB/s
Compression speed: 97.09 MB/s
Decompress speed: 111.05 MB/s
AES256/GCM speed: 22.43 MB/s
Verify speed: 50.26 MB/s
┌───────────────────────────────────┬──────────────────┐
│ Name │ Value │
╞═══════════════════════════════════╪══════════════════╡
│ TLS (maximal backup upload speed) │ 5.53 MB/s (0%) │
├───────────────────────────────────┼──────────────────┤
│ SHA256 checksum computation speed │ 94.44 MB/s (5%) │
├───────────────────────────────────┼──────────────────┤
│ ZStd level 1 compression speed │ 97.09 MB/s (13%) │
├───────────────────────────────────┼──────────────────┤
│ ZStd level 1 decompression speed │ 111.05 MB/s (9%) │
├───────────────────────────────────┼──────────────────┤
│ Chunk verification speed │ 50.26 MB/s (7%) │
├───────────────────────────────────┼──────────────────┤
│ AES256 GCM encryption speed │ 22.43 MB/s (1%) │
└───────────────────────────────────┴──────────────────┘


I know very well that my bottleneck concerns the low banwidth that is 5 Mb / s. (through a digital divide WAN)
The problem, however, is that by synchronizing data at 5 Mb / s are not transferred, there is some dead time between one chunck and another:

2022-10-05T11:29:01+02:00: starting new backup reader datastore 'local': "/backup"
2022-10-05T11:29:01+02:00: protocol upgrade done
2022-10-05T11:29:01+02:00: GET /download
2022-10-05T11:29:01+02:00: download "/backup/vm/100/2022-09-28T22:30:04Z/index.json.blob"
2022-10-05T11:29:01+02:00: GET /download
2022-10-05T11:29:01+02:00: download "/backup/vm/100/2022-09-28T22:30:04Z/drive-ide1.img.fidx"
2022-10-05T11:29:01+02:00: register chunks in 'drive-ide1.img.fidx' as downloadable.
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/7bfa/7bfa4b5b4d4014fb30fd046cd3ffa57e898079923423b5791238eefc3f5f4bb3"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/5990/59904d09dfefc7d50a4c5bc16a634cef6725fe296a3fecea3402e2b16009d562"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/1725/172560ed4bcfd687dc2ffc2ff1b7e96e15967fd58b85ae8c24b185b380d78972"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/ccb7/ccb7beb7fabd7db12f35e17042794b1a0795a3098a2035cff9682a80fad254fb"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/62e5/62e563b7e1676f8c7ac880fff4a2d5e88819e37cd619209fe47b3abd7e026555"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/83f7/83f78b44dcdf047b42e788d0b8b57914978d8c36a52577b08a46560d7abc61e9"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/a056/a0561a7c0a482787ab1d34e9da702676bbe8b96376a98923005375930537b504"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/69e6/69e6820849a2847e01e8045911963a0118ac18e5bdb6a0a6345dac806b1be604"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/8ab5/8ab555cbea6e9b44a8535cb46d61fedbc41920452049b5c9f40f4ca03c4e2d57"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/f590/f5909e6c67c3538c541b3343595df8782e012f2dcbbc17dfd1686b160a1aba77"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/8c8c/8c8cd43acc21c9bd174d998ff145676f3cbe88d49c76fc0078d78b174f7d0586"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/9e39/9e396ec8c07a73e5609a16bb8e15d39adefe5e7f9d0479a0ac872607e0c28372"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/c4f2/c4f211bd3b1a6f183a0b02a31ea9a0cdf810ff7583831e6d7ba3e8e7ce7a0b8b"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/ea16/ea165a18ac508fa42d793854065946b515c477fcae95b5ecd5e62851f66855e0"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/9292/9292064d8d2ee8d33ffdd4fa354a46a28fdd7e3e0ac506936bfb8a147a413611"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/8340/8340fa897c7b44bdbc4fd493784eded14faa6ed2d4f86692716843604143bc43"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/7215/7215e08d660b12929aa9fbdf4c82f9f4ed9c341010ddb34e1bf22b952915eb3a"
2022-10-05T11:29:55+02:00: GET /chunk
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/8bde/8bde80a4f92b99f425d95decbb959317f274609650fca419806036f04c6bc0f8"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/cbb9/cbb9032069165744c26b38ad2d028d5ae799b3d3c799a8c7402aceb2efca16d1"
2022-10-05T11:29:55+02:00: download chunk "/backup/.chunks/884d/884d0d6629d1e8843b6543ab317f505da01cbe2331413c79a14256349a6d0fde"
2022-10-05T11:34:28+02:00: GET /chunk
2022-10-05T11:34:28+02:00: download chunk "/backup/.chunks/b833/b833594ddfb16d24715a945b5bf317e8e547ac9eb13d4fc99d54bdc61277534a"
2022-10-05T11:36:27+02:00: GET /chunk
2022-10-05T11:36:27+02:00: download chunk "/backup/.chunks/e65a/e65a93d443b79164889f4daee8ba914b9d06f80111af81ddefb9bf7a4410ed83"
2022-10-05T11:39:35+02:00: GET /chunk
2022-10-05T11:39:35+02:00: download chunk "/backup/.chunks/4930/493025b2772b9a757c59a166c4fb48e2b651bf94a5d0965649fda5472bffc796"
2022-10-05T11:43:42+02:00: GET /chunk
2022-10-05T11:43:42+02:00: download chunk "/backup/.chunks/1139/11391ca94bf60c8748d1538a55ce2901536d765133e4807433e09d93f3bbb422"
2022-10-05T11:47:15+02:00: GET /chunk
2022-10-05T11:47:15+02:00: download chunk "/backup/.chunks/8e48/8e486ac89908497972b9edf262608db5b7936fae797d0d719159feebb7fc0e6a"
2022-10-05T11:51:12+02:00: GET /chunk
2022-10-05T11:51:12+02:00: download chunk "/backup/.chunks/d925/d92502b1beb57941caa802eed878bff88e27536885bfa67f2aed6095d7a04166"

from what I see, only one chunk is downloaded every 3/4 minutes
I also see this on the local PBS:



Is this normal behavior? if it is normal what is the reason why there are these dead times?
Backup from PVE to local PBS is fast as you can see below:

INFO: Starting Backup of VM 100 (qemu)
INFO: Backup started at 2022-10-05 00:30:00
INFO: status = running
INFO: VM Name: PDC
INFO: include disk 'ide1' 'volume:100/vm-100-disk-0.qcow2' 50G
INFO: backup mode: snapshot
INFO: ionice priority: 7
INFO: creating Proxmox Backup Server archive 'vm/100/2022-10-04T22:30:00Z'
INFO: issuing guest-agent 'fs-freeze' command
INFO: issuing guest-agent 'fs-thaw' command
INFO: started backup task '119b409c-bae4-4824-97cc-f8debd4d079f'
INFO: resuming VM again
INFO: ide1: dirty-bitmap status: OK (540.0 MiB of 50.0 GiB dirty)
INFO: using fast incremental mode (dirty-bitmap), 540.0 MiB dirty of 50.0 GiB total
INFO: 63% (344.0 MiB of 540.0 MiB) in 3s, read: 114.7 MiB/s, write: 113.3 MiB/s
INFO: 100% (540.0 MiB of 540.0 MiB) in 5s, read: 98.0 MiB/s, write: 98.0 MiB/s
INFO: backup was done incrementally, reused 49.48 GiB (98%)
INFO: transferred 540.00 MiB in 5 seconds (108.0 MiB/s)
INFO: adding notes to backup
INFO: Finished Backup of VM 100 (00:00:06)
INFO: Backup finished at 2022-10-05 00:30:06

 

[fabian]

from what I see, only one chunk is downloaded every 3/4 minutes

no, you are misreading the logs. 20 chunks are downloaded in parallel, but it takes around 3,5 minutes until the first has fully arrived at the other end and the next one is requested, then another 2 minutes until the second (of the initial 20!) is there, and so on. I assume your link is not only low-bandwidth, but also (somewhat) high latency, and that really affects the throughput of HTTP2 connections (as used by our backup reader/writer). there's basically a limited amount of data that is allowed to be in-flight, and the back and forth to signal "hey, I got some data, you can send the next part" adds up when each round-trip takes longer than "normal".

see https://bugzilla.proxmox.com/show_bug.cgi?id=4182 for some more discussion of exactly this issue.

 

[m0m0]

Ok Fabian, Thank you for the tip on reading logs..

Right now I am checking that after 90 minutes I have transferred 50 chunks (not counting the loading of the first 20). so on average 1 chunk every 1.8 minutes which is about 108 seconds. But this runs counter to what the benckmark says: "Uploaded 13 chunks in 9 seconds".

Either way my current ping while I'm syncing, so using bandwidth is this:

root@pbs:~# ping 192.168.1.100
PING 192.168.1.100 (192.168.1.100) 56(84) bytes of data.
64 bytes from 192.168.1.100: icmp_seq=1 ttl=62 time=54.0 ms
64 bytes from 192.168.1.100: icmp_seq=2 ttl=62 time=168 ms
64 bytes from 192.168.1.100: icmp_seq=3 ttl=62 time=54.0 ms
64 bytes from 192.168.1.100: icmp_seq=4 ttl=62 time=85.7 ms
64 bytes from 192.168.1.100: icmp_seq=5 ttl=62 time=54.4 ms
64 bytes from 192.168.1.100: icmp_seq=6 ttl=62 time=162 ms
64 bytes from 192.168.1.100: icmp_seq=7 ttl=62 time=45.4 ms
64 bytes from 192.168.1.100: icmp_seq=8 ttl=62 time=44.7 ms
64 bytes from 192.168.1.100: icmp_seq=9 ttl=62 time=52.3 ms
64 bytes from 192.168.1.100: icmp_seq=10 ttl=62 time=156 ms
64 bytes from 192.168.1.100: icmp_seq=11 ttl=62 time=115 ms
64 bytes from 192.168.1.100: icmp_seq=12 ttl=62 time=53.4 ms
64 bytes from 192.168.1.100: icmp_seq=13 ttl=62 time=192 ms
64 bytes from 192.168.1.100: icmp_seq=14 ttl=62 time=48.2 ms

in fact a bad unstable latency..

 

[fabian]

the benchmark is quite simple, it queues chunks for 5 seconds and then waits for them to be uploaded. the chunks are also identical. so likely the benchmark causes less congestion.