Forwarded to devs Slowdown on backup transfers when using multivolume backup

[Andreas79]

Username: Andreas79

TITLE

Slowdown on backup transfers when using multivolume backup

PRODUCT, VERSION, OPERATING SYSTEM, ARCHITECTURE

Plesk Obisidian 18.0.34, Centos 7

PROBLEM DESCRIPTION

On manual or scheduled backup
Using external storage (tried FTP and SFTP).
Using 'create multivolume backup'
The backup will start running and creating the different tars with the correct size. It transfers the files to the remote server. After the 1st or sometimes the 2nd part the transfer slows down. This becomes so slow that an backup never finished in a day.
I have started an backup with a volume size of 100MB. and cancelled this one after 10 minutes.
The I started a second backup with a volume size of 10GB.

Monitoring file sizes on the external server I see
14:41 100MB backup_xxx.tar
14:43 100MB backup_xxx.tar1
15:22 91MB backup_xxx.tar2
15:22 2,1GB backup_yyy.tar

The last file is my second backup run. You see, the first backup is still uploading taking far much time that tar1. In the meantime the second backup already transferred more that 2GB of data. Same servers, same connection

Disabling the multivolume backup solves my backup problems as they complete in a reasonable time

STEPS TO REPRODUCE

Start an backup from PLESK or any scheduled backup.
Use remote storage (FTP or SFTP)
Enable multivolume backup
In my case I chose for a full backup

ACTUAL RESULT

Backup never completes in a day

EXPECTED RESULT

Backup complete in a reasonable timespan

ANY ADDITIONAL INFORMATION



YOUR EXPECTATIONS FROM PLESK SERVICE TEAM

Confirm bug

 

[Aytalina]

Hello Andreas79,

Thank you for your report.

I checked the issue according to provided "Steps To Reproduce", but all multivolume backups on my testing environment were created successfully.

For further investigation, could you please perform the following:

- Enable Plesk debug mode (without 'show.sql_query' and 'show.util_exec_io'):

How to enable/disable Plesk debug mode

Applicable to: Plesk for Linux Plesk for Windows Question How to enable/disable debug logging in Plesk? Answer The debug mode can be enabled either via the Plesk Panel.ini Editor extension in Pl...

support.plesk.com

- Enable Plesk Backup debug mode (Please refer to section "Additional debug logging for pmmcli-rc utility"):

How to enable debug mode for Plesk backup operations

Applicable to: Plesk for Linux Plesk for Windows Question How to enable debug mode for Plesk backup operations? Answer For backup tasks that are performed in Plesk Backup Manager Nothing n...

support.plesk.com

- Reproduce the issue by creating a multivolume backup
- Collect /var/log/plesk/PMM/backup-YYYY-MM-DD-HH-MM-SS-
- Collect /var/log/plesk/PMM/migration.log.YYYY-MM-DD-HHMMSS
where YYYY-MM-DD-HH-MM-SS stands for your backup creation time.
- Disable the debug mode
- DM me the files you collected

Thank you.

 

[Bitpalast]

Not my intention to add a different topic to this thread, but maybe this can help to tackle the above issue:
This issue sounds familiar to one that we have had for a very long time (> 1 year) with restores from single volume backups. A restore starts fast with somethink like 45 MB/s, then suddenly becomes slower. And slower. And slower. And it normally resides at 1.5 MB/s after it ran for an hour or two. This is during the FTP download from an FTP storage space. However, the same process done with sftp manually completes with high speed all through the download. What the above user describes seems to be a similar behavior when backing up data. Initial process runs fast, then suddenly the transfer speed decreases to a point where it takes "forever" to complete. I never figured out why this happens. When I restore data from a backup by first downloading the backup archives manually to the local server and then running the Plesk command to import these into Plesk, all works fine.

 

[Andreas79]

Thanks for the feedback. I am generating the logs since this morning and share them later today.
Note, the backup does complete. However it can take several days.
@Peter Debik > Yes, I have seen that as well. I always blamed my patience for it

 

[Andreas79]

I send the logs in a DM

 

[Aytalina]

Hello Andreas79,

Thank you for waiting.

From the provided logs I see that the most consuming operation is uploading volumes to the storage, please check the time difference (I removed your personal data):

[2021-03-12 09:57:44.415|46861] DEBUG [panel] Created volume: {volume}.tgz1 (34547170)
[2021-03-12 09:57:44.415|46861] DEBUG [panel] Export file
2021-03-12 10:47:23.206 DEBUG (7) [extension/sftp-backup]: Request log:
* Trying 1.2.3.4:22...
* Connected to yourhost.tld (1.2.3.4) port 22 (#0)
* SSH MD5 fingerprint:
* SSH authentication methods available:
* Initialized password authentication
* Authentication complete
* Connection #0 to host yourhost.tld left intact

[2021-03-12 10:47:23.228|47059] INFO: The utility output: {"size":104857600}

(60 minutes)

[2021-03-12 10:50:33.780|46861] DEBUG [panel] Export file (209715200/+104857600/2)
2021-03-12 11:40:16.034 DEBUG (7) [extension/sftp-backup]: Request log:
* Trying 1.2.3.4:22...
* Connected to yourhost.tld (1.2.3.4) port 22 (#0)
* SSH MD5 fingerprint:
* SSH authentication methods available:
* Initialized password authentication
* Authentication complete
* Connection #0 to host yourhost.tld left intact

[2021-03-12 11:40:16.061|47059] INFO: The utility output: {"size":104857600}
[2021-03-12 11:40:16.067|47059] INFO: RepositoryTransportExternal::CloseFile
[2021-03-12 11:40:16.067|47059] INFO: The utility input: close
[2021-03-12 11:40:16.100|47059] INFO: The utility executed with exit code: 0, stdout:

(50 minutes)

021-03-12 11:44:26.954 DEBUG (7) [extension/sftp-backup]: Upload content to
[2021-03-12 11:44:38.842|46861] DEBUG [panel] Created volume: {volume}.tgz4 (104857600)
[2021-03-12 11:44:38.842|46861] DEBUG [panel] Export file .tgz4 (209715200/+104857600/2)
2021-03-12 12:32:53.926 DEBUG (7) [extension/sftp-backup]: Request log:
* Trying 1.2.3.4:22:22...
* Connected to yourhost.tld (1.2.3.4) port 22 (#0)
* SSH MD5 fingerprint:
* SSH authentication methods available:
* Initialized password authentication
* Authentication complete
* Connection #0 to host yourhost.tld left intact

[2021-03-12 12:32:53.956|47059] INFO: The utility output: {"size":104857600}
[2021-03-12 12:32:53.964|47059] INFO: RepositoryTransportExternal::CloseFile
[2021-03-12 12:32:53.964|47059] INFO: The utility input: close
[2021-03-12 12:32:54.000|47059] INFO: The utility executed with exit code: 0, stdout:

(50 minutes)

You can find other long operations in your backup.log.

Plesk backup utility waits when the volume upload is finished and, therefore, the whole backup process takes a significant amount of time.

A couple of questions:
- Was the issue reproduced before? (if you performed an upgrade)
- Network issues could lead to this behavior, please try to upload, for instance, 100MB file via SFTP, FTP using curl from the Plesk machine to your backup storage
- What will happen if you define 1GB instead of 100MB volume?

Please do not forget to disable debug logging once you finish collecting logs.

Thank you

 

[Andreas79]

Hi there. Thanks for looking at my logs.
As you see the first 100 MB uploaded in a flash:
[2021-03-12 09:57:35.657|46861] DEBUG [panel] Created volume: {volume}.tgz (104857600)
[2021-03-12 09:57:35.657|46861] DEBUG [panel] Export file .tgz (104857600/+104857600/1)
---
[2021-03-12 09:57:44.415|46861] DEBUG [panel] Created volume: {volume}.tgz1 (34547170)
[2021-03-12 09:57:44.415|46861] DEBUG [panel] Export file
---
[2021-03-12 10:50:33.780|46861] DEBUG [panel] Export file (209715200/+104857600/2)

This is in the same minute. My original report is that the second and follow up backups are taking forever to download. As you can see in my original report, a second backup without multi volume, started half hour later was able to export 2.1 GB while my first backup attempt did not reach the 300 MB mark.

The same behaviour is seen on the remote server chekcing the timestamps. I removed this test backup but I will show you some timestamps from another backup I made:

1073741824 Mar 3 01:24 backup_2102250114_2103030109.tar
1073741824 Mar 3 01:25 backup_2102250114_2103030109.tar1
1073741824 Mar 3 09:08 backup_2102250114_2103030109.tar2

If the network speed is the issue, why I am able to make a full server backup without multivolume in 2 hours, while with multivolume it does not finish in a day.

- Was the issue reproduced before? (if you performed an upgrade)
> This problem became appearant as backups more and more often failed to complete. I started looking at the reasons recentley so I can not tell you when this problem started

- Network issues could lead to this behavior, please try to upload, for instance, 100MB file via SFTP, FTP using curl from the Plesk machine to your backup storage
> Not a problem, it completes in 1 - 2 minutes

- What will happen if you define 1GB instead of 100MB volume?
> The first tar upload in a few minutes. The second shows the same slowdown.

 

[Aytalina]

Hello Andreas79,

Thank you for your reply.
The issue is under investigation. We will keep you informed.

 

[Aytalina]

Hello Andreas79,

According to the logs, your average upload speed to the storage is 3.7 MB/s and your full backup size is ~50Gb, so the time of upload could be ~4 hours.
But as we discussed you have a significant drop in the upload speed ~100 times (~0.034 MB/s) after the first volumes.

We create a new connection and logging in each time we upload a new volume.
It could be possible that on the storage side there is a limitation to the number of connections per hour. Please try to upload a file 20 times in a row using curl, for instance.

curl "sftp://example.com" --user "a:b" -T "./myfile.tar"

Also, you can try to create a multivolume backup to another storage, if possible.

Some logs with speed calculation for your reference:

2021-03-12 09:57:40.630 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar': 0/104857600/0
2021-03-12 10:47:23.206 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 2983 s = 0.034 MB/s
2021-03-12 10:48:52.785 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar1': 0/104857600/0
2021-03-12 10:49:21.044 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 29 s = 3.45 MB/s
2021-03-12 10:49:23.172 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar2': 0/104857600/0
2021-03-12 10:49:49.094 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 26 s = 3.85 MB/s
2021-03-12 10:49:51.666 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar3': 0/104857600/0
2021-03-12 10:50:18.775 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 27 s = 3.85 MB/s
2021-03-12 10:50:20.743 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar4': 0/104857600/0
2021-03-12 11:40:16.034 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 2996 s = 0.034 MB/s
2021-03-12 11:40:17.778 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar5': 0/104857600/0
2021-03-12 11:40:45.664 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 28 s = 3.57 MB/s
2021-03-12 11:40:47.545 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar6': 0/104857600/0
2021-03-12 11:41:13.637 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 26 s = 3.85 MB/s
2021-03-12 11:42:56.602 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar7': 0/104857600/0
2021-03-12 11:43:23.794 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 27 s = 3.70 MB/s
2021-03-12 11:43:25.849 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar8': 0/104857600/0
2021-03-12 11:43:53.940 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 28 s = 3.57 MB/s
2021-03-12 11:43:55.719 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar9': 0/104857600/0
2021-03-12 11:44:25.147 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 30 s = 3.33 MB/s
2021-03-12 11:44:26.954 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar10': 0/104857600/0
2021-03-12 12:32:53.926 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 2853 s = 0.035 MB/s
2021-03-12 12:32:56.492 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar11': 0/104857600/0
2021-03-12 12:33:23.683 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 27 s = 3.70 MB/s
2021-03-12 12:33:26.737 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar12': 0/104857600/0
2021-03-12 13:23:25.596 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 2999 s = 0.033 MB/s
2021-03-12 13:23:27.652 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar13': 0/104857600/0
2021-03-12 13:23:55.140 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 28 s = 3.57 MB/s
2021-03-12 13:23:57.812 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar14': 0/104857600/0
2021-03-12 14:12:40.440 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 2983 s = 0.034 MB/s
2021-03-12 14:12:42.341 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar15': 0/104857600/0
2021-03-12 14:13:09.888 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 27 s = 3.70 MB/s
2021-03-12 14:13:12.463 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar16': 0/104857600/0
2021-03-12 14:13:38.267 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 26 s = 3.70 MB/s
2021-03-12 14:13:40.589 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar17': 0/104857600/0
2021-03-12 14:14:07.797 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 27 s = 3.70 MB/s
2021-03-12 14:14:09.876 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar18': 0/104857600/0
2021-03-12 14:14:36.770 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 27 s = 3.70 MB/s
2021-03-12 14:14:39.166 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar19': 0/104857600/0
2021-03-12 14:15:08.830 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 29 s = 3.45 MB/s
2021-03-12 14:15:49.837 DEBUG (7) [extension/sftp-backup]: Upload content to 'sftp://yourdomain.tld//pleskbackup/backup_2103120957.tar20': 0/104857600/0
2021-03-12 15:05:19.866 DEBUG (7) [extension/sftp-backup]: Request log:
# 100 MB / 3030 s = 0.033 MB/s

 

[Andreas79]

Sorry, just see your answer.
That would make sense. I will investigate and come back

 

[Bitpalast]

Same problem here with restores, not backups.
ftpForbidReuseConnection = 1
has not solved it. So concurrent FTP transfers might not be the cause.

 

[homberger]

Did anyone ever find a solution to this slowdown of multi volume backups? I am affected by this problem too.