Writes to the rclone mount are extremely slow / rclone slows down the system during copy

[Animosity022]

That would not change the Link command being issued by the application though and I don't use anything but a regular old GSuite single drive.

If it works for you, just hit a quick rename on a movie with a debug log as I am very curious if it does not issue a link command.

[Animosity022]

Let me make a new post rather than continue to hijack this one as it's not the OP's issue.

[s0mm3r]

If it works for you, just hit a quick rename on a movie with a debug log as I am very curious if it does not issue a link command.

I've posted a log above

Writes to the rclone mount are extremely slow / rclone slows down the system during copy

I just started my old vps again and did a move there and again, took just seconds mount command: /usr/bin/rclone mount -vvv \ --config=/home/.config/rclone/rclone.conf \ --allow-other \ --cache-workers=8 \ --cache-writes \ --no-modtime \ --drive-use-trash \ --stats=0 \ --checkers=16 \ --vfs-cache-mode writes \ --dir-cache-time=60m \ --cache-dir=/mnt/sdb1/rclonecache \ --cache-info-age=60m \ …

[Animosity022]

Your post is different from the question that @darthShadow and I are asking.

Yours is instant because it's writing it locally first via the writes cache mode.

2019/09/16 18:39:34 DEBUG : Filme/Filme/Gnaw (2017)/: Link: req=Link [ID=0x19128 Node=0x10f Uid=0 Gid=0 Pid=14834] node 102 to "avcihd-apartment212-avc.mkv.backup~", old=Filme/Filme/Gnaw (2017)/avcih
d-apartment212-avc.mkv
2019/09/16 18:39:34 DEBUG : Filme/Filme/Gnaw (2017)/: >Link: new=<nil>, err=function not implemented

[s0mm3r]

Your post is different from the question that @darthShadow and I are asking.

Yours is instant because it's writing it locally first via the writes cache mode.

and why does this not work on my new server?
where the writes are cached too?
with the same commands?
(this is what I described in issue #4 in my OP: Writes to the rclone mount are extremely slow / rclone slows down the system during copy)

isn't this where the rename happens?
it actually says "rename"

2019/09/16 18:39:34 DEBUG : Filme/Filme/Gnaw (2017)/: Rename: oldName="avcihd-apartment212-avc.mkv", newName="Apartment.212.2017.Bluray-1080p.mkv", newDir=Filme/Filme/Apartment 212 (2017)/
2019/09/16 18:39:35 INFO  : Filme/Filme/Gnaw (2017)/avcihd-apartment212-avc.mkv: Moved (server side)
2019/09/16 18:39:35 DEBUG : Filme/Filme/Gnaw (2017)/avcihd-apartment212-avc.mkv: Updating file with Filme/Filme/Apartment 212 (2017)/Apartment.212.2017.Bluray-1080p.mkv 0xc0136d9cc0
2019/09/16 18:39:35 DEBUG : Filme/Filme/Gnaw (2017)/: >Rename: err=<nil>

[Animosity022]

Yes a rename is a server side move and happens instantly.

If you are running Radarr on each and doing the same commands, it would be whatever is different from the servers that is creating the issue as the app is what delivers the command to "Link" or "Rename".

If that log is from a Radarr Organize, I'd love to know what's different in terms of OS/Mono version /etc.

[Animosity022]

I feel like I just cured world hunger or something.

@darthShadow @s0mm3r

The issue is the version of Mono that you have.

V6 does the Link and fails.
V5 Links, but does the rename.

I downgraded and locked my mono on v5 for now.

Here is a working log.

[felix@gemini logs]$ tail -f rclone.log | grep -i strong




2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Lookup: name="12 Strong (2018).mp4.backup~"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Lookup: name="12 Strong (2018).mp4.backup~"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Lookup: name="12 Strong (2018).mp4.backup~"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Lookup: name="12 Strong (2018).mp4.backup~"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Link: req=Link [ID=0x175c2a Node=0x1fb1 Uid=1000 Gid=1000 Pid=7685] node 11107 to "12 Strong (2018).mp4.backup~", old=Movies/12 Strong (2018)/12 Strong (2018).mp4
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Link: new=<nil>, err=function not implemented
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Lookup: name="12 Strong (2018).mp4.backup~"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: Lookup: name="12 Strong (2018).mp4.backup~"
2019/09/16 15:32:10 DEBUG : Movies/12 Strong (2018)/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Lookup: name="12.Strong.2018"
2019/09/16 15:32:10 DEBUG : Movies/: Mkdir: name="12.Strong.2018"
2019/09/16 15:32:11 DEBUG : Movies/: >Mkdir: node=Movies/12.Strong.2018/, err=<nil>
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: Attr:
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: Setattr: stat=Setattr [ID=0x175c56 Node=0x3bd1 Uid=0 Gid=0 Pid=7685] uid=1000 gid=1000 handle=INVALID-0x0
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: >Setattr: err=<nil>
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: Attr:
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: Setattr: stat=Setattr [ID=0x175c58 Node=0x3bd1 Uid=0 Gid=0 Pid=7685] atime=2019-09-16 15:32:10.922179322 -0400 EDT mtime=2019-09-16 15:32:10.922179322 -0400 EDT handle=INVALID-0x0
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: >Setattr: err=<nil>
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: Attr:
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: Lookup: name="12.Strong.2018.mp4"
2019/09/16 15:32:11 DEBUG : Movies/12.Strong.2018/: >Lookup: node=<nil>, err=no such file or directory
2019/09/16 15:32:11 DEBUG : Movies/12 Strong (2018)/: Rename: oldName="12 Strong (2018).mp4", newName="12.Strong.2018.mp4", newDir=Movies/12.Strong.2018/
2019/09/16 15:32:12 INFO  : Movies/12 Strong (2018)/12 Strong (2018).mp4: Moved (server side)
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/12 Strong (2018).mp4: Updating file with Movies/12.Strong.2018/12.Strong.2018.mp4 0xc0005388c0
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Rename: err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12.Strong.2018/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12.Strong.2018/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12.Strong.2018/12.Strong.2018.mp4: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12.Strong.2018/12.Strong.2018.mp4: >Attr: a=valid=1000h0m0s ino=0 size=9534563712 mode=-rw-rw-r--, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: ReadDirAll:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >ReadDirAll: item=0, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: Attr:
2019/09/16 15:32:12 DEBUG : Movies/12 Strong (2018)/: >Attr: attr=valid=1000h0m0s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2019/09/16 15:32:12 DEBUG : Movies/: Remove: name="12 Strong (2018)"

[s0mm3r]

If that log is from a Radarr Organize, I'd love to know what's different in terms of OS/Mono version /etc.

yes it is and that is what I am trying to figure out the past 2 weeks
OS is both ubuntu 18.04.3 with
new server: Mono version 6.0.0.327 (tarball Thu Aug 29 21:15:03 UTC 2019)
old server: Mono version 5.20.1.34 (tarball Tue Jul 16 22:52:32 UTC 2019)
I've updated the old server to the current stable v6 and bam! the issue is the same

downgrading to v5 now

[s0mm3r]

The issue is the version of Mono that you have.

V6 does the Link and fails.
V5 Links, but does the rename.

I downgraded and locked my mono on v5 for now.

yep, I can confirm, I've noticed it just now
can you hit me with the repo link you used?

thank you

[Animosity022]

For Ubuntu, there is a link here that shows how to downgrade it:

Permission issues after Mono 6 upgrade

[ncw (Nick Craig-Wood)]

The issue is the version of Mono that you have.

V6 does the Link and fails.
V5 Links, but does the rename.

Is this something rclone can work around? Can you isolate the sequence of calls it is making and ideally make a reproduction just using shell commands?

[darthShadow (Anagh Kumar Baranwal)]

Excellent catch. I still hadn't upgraded to Mono 6.0 due to reports of various issues with both Sonarr & Radarr using it. Looks like this is another one of them. Probably would be helpful to paste the debug/trace logs from Sonarr/Radarr using both versions to see if the developers can add some workaround for it

[Animosity022]

I'll have to spend some time and see how if I can grab the full set of logs and such for Sonarr / Radarr. There are a number of posts/comments complaining about various things about v6 vs v5, but I hadn't even though about it until @darthShadow mentioned it was working for him and the OP having it work on an 'old' server.

In theory, it makes sense on the Linux side to link rather than move as it saves disk space and the move should all be on the same physical disk using the organize/rename feature.

Let me dig up the logs and post a post on the Sonarr side and get their feedback on it.

[darthShadow (Anagh Kumar Baranwal)]

Probably the same issue:

Issue: mono 6.0.0 File.Move on same partition (SD Card, FAT) takes as long as File.Copy (and so is ~1000x slower than mono 5.x)

And 2 PR(s) for it:

FileSystem.Unix.File.Move uses "rename" in more cases

Fix issue mono/mono#16435, by improving behavior of FileSystem.Unix File.Move

[s0mm3r]

downgrade to v5 fixed 3 of my issues
issue #2 "slow write speed to disk" remains
I'll close this now, dig into it and, if needed, will open a new post

thanks for your support
was very helpfull

regards

[s0mm3r]

I'll have to spend some time and see how if I can grab the full set of logs and such for Sonarr / Radarr. There are a number of posts/comments complaining about various things about v6 vs v5, but I hadn't even though about it until @darthShadow mentioned it was working for him and the OP having it work on an 'old' server.

In theory, it makes sense on the Linux side to link rather than move as it saves disk space and the move should all be on the same physical disk using the organize/rename feature.

Let me dig up the logs and post a post on the Sonarr side and get their feedback on it.

after a downgrade to v5 it also works on my 'new' server
I have radarr debug logs if you need them, trace was not enabled

regards

[s0mm3r]

maybe I just don't see it or my account does not have sufficient rights to close this / set it as solved / mark a reply as solution

it is solved and the solution is to downgrade to v5:

Writes to the rclone mount are extremely slow / rclone slows down the system during copy

For Ubuntu, there is a link here that shows how to downgrade it:

[Animosity022]

I changed the tag to a question and marked a solution for you.

We normally only have question/bug with solutions rather than every topic.