High IO during encrypted FTP-Backup

Help and Support
1

Hi everyone.

What is the problem you are having with rclone?

I am having a problem on a proxmox server. I am trying to backup a 50 GB tar.gz- file to a ftp server.
During the upload the IO wait becomes very high even though I am running it with ionice -c3.
I tried bwlimit which helps a little, but slows things down of course.
Any idea on how to improve that?
Is the encryption-function creating local temp-files or what is causing the high IO?

What is your rclone version (output from rclone version)

rclone v1.51.0-239-g37a53570-beta (just updated to latest beta - same issue)

Which OS you are using and how many bits (eg Windows 7, 64 bit)

debian 10.3 64bit

Which cloud storage system are you using? (eg Google Drive)

FTP

The command you were trying to run (eg rclone copy /tmp remote:tmp)

ionice -c3 nice -n19 rclone copy $TARFILE $RCLONEFTPREMOTE --bwlimit 50M --log-file $LOGFILE -vv

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

COnfig:
[ip--ftp]
type = ftp
host = 192.168.22.
user = *
pass = *

[ip--ftp-encrypted]
type = crypt
remote = ip--ftp:/server20
filename_encryption = off
directory_name_encryption = false
password = *

Logfile:
2020/05/01 01:37:54 DEBUG : rclone: Version "v1.51.0-239-g37a53570-beta" starting with parameters ["rclone" "copy" "/backup/autobackup/tar/2020-04-30--22-00-01.tar.gz" "ip--ftp-encrypted:/" "--bwlimit" "50M" "--log-file" "/var/log/_backup.log" "-vv"]
2020/05/01 01:37:54 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2020/05/01 01:37:54 INFO : Starting bandwidth limiter at 50MBytes/s
2020/05/01 01:37:54 DEBUG : ftp://192.168.22.:21/server20/.bin: Connecting to FTP server
2020/05/01 01:37:54 DEBUG : ftp://192.168.22.:21/server20: Connecting to FTP server
2020/05/01 01:37:54 DEBUG : 2020-04-30--22-00-01.tar.gz: Need to transfer - File not found at Destination
2020/05/01 01:38:54 INFO :
Transferred: 2.771G / 50.431 GBytes, 5%, 47.273 MBytes/s, ETA 17m12s
Transferred: 0 / 1, 0%
Elapsed time: 1m0.0s
Transferring:

  •               2020-04-30--22-00-01.tar.gz:  5% /50.431G, 47.577M/s, 17m5s

2020/05/01 01:39:54 INFO :
Transferred: 5.507G / 50.431 GBytes, 11%, 46.990 MBytes/s, ETA 16m18s
Transferred: 0 / 1, 0%
Elapsed time: 1m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 10% /50.431G, 45.280M/s, 16m55s

2020/05/01 01:40:54 INFO :
Transferred: 8.263G / 50.431 GBytes, 16%, 47.008 MBytes/s, ETA 15m18s
Transferred: 0 / 1, 0%
Elapsed time: 2m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 16% /50.431G, 47.473M/s, 15m9s

2020/05/01 01:41:54 INFO :
Transferred: 11.187G / 50.431 GBytes, 22%, 47.732 MBytes/s, ETA 14m1s
Transferred: 0 / 1, 0%
Elapsed time: 3m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 22% /50.431G, 49.925M/s, 13m24s

2020/05/01 01:42:54 INFO :
Transferred: 13.900G / 50.431 GBytes, 28%, 47.447 MBytes/s, ETA 13m8s
Transferred: 0 / 1, 0%
Elapsed time: 4m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 27% /50.431G, 43.475M/s, 14m20s

2020/05/01 01:43:54 INFO :
Transferred: 16.435G / 50.431 GBytes, 33%, 46.747 MBytes/s, ETA 12m24s
Transferred: 0 / 1, 0%
Elapsed time: 5m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 32% /50.431G, 33.098M/s, 17m31s

2020/05/01 01:44:54 INFO :
Transferred: 19.102G / 50.431 GBytes, 38%, 46.573 MBytes/s, ETA 11m28s
Transferred: 0 / 1, 0%
Elapsed time: 6m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 37% /50.431G, 45.478M/s, 11m45s

2020/05/01 01:45:54 INFO :
Transferred: 21.925G / 50.431 GBytes, 43%, 46.774 MBytes/s, ETA 10m24s
Transferred: 0 / 1, 0%
Elapsed time: 7m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 43% /50.431G, 44.094M/s, 11m1s

2020/05/01 01:46:54 INFO :
Transferred: 24.527G / 50.431 GBytes, 49%, 46.511 MBytes/s, ETA 9m30s
Transferred: 0 / 1, 0%
Elapsed time: 8m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 48% /50.431G, 45.782M/s, 9m39s

2020/05/01 01:47:54 INFO :
Transferred: 27.263G / 50.431 GBytes, 54%, 46.529 MBytes/s, ETA 8m29s
Transferred: 0 / 1, 0%
Elapsed time: 9m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 54% /50.431G, 49.179M/s, 8m2s

2020/05/01 01:48:54 INFO :
Transferred: 29.846G / 50.431 GBytes, 59%, 46.307 MBytes/s, ETA 7m35s
Transferred: 0 / 1, 0%
Elapsed time: 10m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 59% /50.431G, 34.957M/s, 10m2s

2020/05/01 01:49:54 INFO :
Transferred: 32.605G / 50.431 GBytes, 65%, 46.372 MBytes/s, ETA 6m33s
Transferred: 0 / 1, 0%
Elapsed time: 11m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 64% /50.431G, 47.336M/s, 6m25s

2020/05/01 01:50:54 INFO :
Transferred: 35.149G / 50.431 GBytes, 70%, 46.144 MBytes/s, ETA 5m39s
Transferred: 0 / 1, 0%
Elapsed time: 12m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 69% /50.431G, 41.475M/s, 6m17s

2020/05/01 01:51:54 INFO :
Transferred: 37.949G / 50.431 GBytes, 75%, 46.262 MBytes/s, ETA 4m36s
Transferred: 0 / 1, 0%
Elapsed time: 13m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 75% /50.431G, 49.214M/s, 4m19s

2020/05/01 01:52:54 INFO :
Transferred: 40.471G / 50.431 GBytes, 80%, 46.047 MBytes/s, ETA 3m41s
Transferred: 0 / 1, 0%
Elapsed time: 14m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 80% /50.431G, 30.926M/s, 5m29s

2020/05/01 01:53:54 INFO :
Transferred: 43.401G / 50.431 GBytes, 86%, 46.294 MBytes/s, ETA 2m35s
Transferred: 0 / 1, 0%
Elapsed time: 15m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 86% /50.431G, 49.556M/s, 2m25s

2020/05/01 01:54:54 INFO :
Transferred: 46.236G / 50.431 GBytes, 92%, 46.417 MBytes/s, ETA 1m32s
Transferred: 0 / 1, 0%
Elapsed time: 16m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 91% /50.431G, 49.839M/s, 1m26s

2020/05/01 01:55:54 INFO :
Transferred: 49.028G / 50.431 GBytes, 97%, 46.486 MBytes/s, ETA 30s
Transferred: 0 / 1, 0%
Elapsed time: 17m59.9s
Transferring:

  •               2020-04-30--22-00-01.tar.gz: 97% /50.431G, 48.141M/s, 29s

2020/05/01 01:56:23 INFO : 2020-04-30--22-00-01.tar.gz: Copied (new)
2020/05/01 01:56:23 INFO :
Transferred: 50.443G / 50.443 GBytes, 100%, 46.544 MBytes/s, ETA 0s
Transferred: 1 / 1, 100%
Elapsed time: 18m29.7s

2020/05/01 01:56:23 DEBUG : 4 go routines active

2

How high I/o are you seeing? According to your log it is reading at at least 48Mbytes/s to copy the file. No it doesn't create a temp file.

3

Could the high IO be from the encryption taking place? I'm curious if you upload something to the remote directly (not via the encrypted remote) if you still get the same IO.

4

Encryption is a small CPU hit and really negligible on IO.

The way ionice works is it doesn't limit IO, just waits for free cycles. If you have free cycles, it's going to consume the free IO.

5

I will try unencrypted upload tonight.

I am aware of the function of ionice. I am just observing services in containers going down during rclone upload while the whole process of backup and creating a tar.gz is not affecting anything.
I limited the bw to 50M temporarily for debug-purposses.

I'll come back to you tomorrow with the results of the unencrypted backup-process.

6

I'd guess you might be running out of CPU rather than IO? ionice -c 3 should have things only using idle IO. I use this for my nightly backups on my Linux box:

 /usr/bin/ionice -c2 -n7 /usr/bin/rsnapshot daily
7

Well, there is not much going on during the night except for some cron-jobs.
So idle-IO seems to be enough for now. I don't see a reason to switch to -c2.
I am also using nice -n19 in combination with ionice.
CPU never passed the 25% usage during nightly backups so I don't think that is it. Also RAM never went beyond 75% usage.

8

I think we can mark this resolved.
The problem was more the TAR before the rclone than the rclone so I will resolve this issue.

Thank you very much for the help!

1 Like
9

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.