Rclone/Plex library scan extremely slow +24h

Hi,
I recently updated rclone to v1.44 (Ubuntu 18.04) and installed the service as per below. Previously I used the cache option and had good performance. After the update I’m experiencing very slow Plex library scans. Especially when adding a new library.

Currently it’s taken more than 24h to add 61 TV-shows. Ad the same time Radarr and Sonarr we not responding when updating the library - Kinda seems like Rclone cannot handle several connections.

My rclone.service file looks like this:

[Unit]
Description=Mount and cache Google drive
After=syslog.target local-fs.target network.target

[Service]
Environment=RCLONEHOME=/home/plexuser/.config/rclone/
Environment=MOUNTTO=/media/PlexCloud

Type=simple
User=root
ExecStartPre=/bin/mkdir -p ${MOUNTTO}
ExecStart=/usr/bin/rclone mount \
        --rc \
        --allow-other \
        --allow-non-empty \
        --buffer-size 256M \
        --dir-cache-time 72h \
        --allow-non-empty \
        --drive-chunk-size 32M \
        --fast-list \
        --umask 002 \
        --vfs-read-chunk-size 128M \
        --vfs-read-chunk-size-limit off \
        --config ${RCLONEHOME}/rclone.conf \
        Gdrive: /media/PlexCloud
ExecStop=/bin/fusermount -u -z ${MOUNTTO}
ExecStop=/bin/rmdir ${MOUNTTO}
Restart=always

[Install]
WantedBy=multi-user.target

And the rclone.conf looks like this:

[Gdrive]
type = drive
scope = drive
token = {"access_token":"***hidden***","token_type":"Bearer",$
root_folder_id = ***hidden***

Please advise what I can change to get decent read/write speeds.
Thanks

Without any log information of what was going on, it’s hard to tell what the error/issue was.

Rclone does fine with a lot going on. If you were copying items via Sonarr/Radarr, they hang up until a file copy is complete, which is normal for those applications. If you were moving large/big files and uploading them directly to the mount, that would be the cause.

I’ll try and get the Rclone files log files and post them.

The use case is that I’m reinstalling a dedicated remote server at Hetzner and at Oneprovider.

  1. All files are already available on GD
  2. Plex/Radarr/Sonarr are all fresh installs
  3. I started with adding TVshows to Plex (with out adding elsewhere)

Step 3 has taken more than 24 hours. I tried this on several hosted servers (different locations) and I tried PlexGuide, GooPlex and manual install of Rclone. All end up with the same result - slow scans and slow start time to play a show.

Also, I think you might be hitting the kernel bug described here:

Yes, I’m affected by the sudden drop in transfer speeds.

@Animosity022 I shared the full log in a PM, and here are some snippets from the DEBUG log:

Initial start up:

2018/10/24 16:05:08 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2018/10/24 16:05:08 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:08 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:08 DEBUG : Movies/: Attr: 
2018/10/24 16:05:08 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:08 DEBUG : /: Lookup: name="NP"
2018/10/24 16:05:08 DEBUG : /: >Lookup: node=NP/, err=<nil>
2018/10/24 16:05:08 DEBUG : NP/: Attr: 
2018/10/24 16:05:08 DEBUG : NP/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:08 DEBUG : /: Lookup: name="TVShows"
2018/10/24 16:05:08 DEBUG : /: >Lookup: node=TVShows/, err=<nil>
2018/10/24 16:05:08 DEBUG : TVShows/: Attr: 
2018/10/24 16:05:08 DEBUG : TVShows/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:08 DEBUG : /: Lookup: name="plex.mp4"
2018/10/24 16:05:08 DEBUG : /: >Lookup: node=plex.mp4, err=<nil>
2018/10/24 16:05:08 DEBUG : plex.mp4: Attr: 
2018/10/24 16:05:08 DEBUG : plex.mp4: >Attr: a=valid=1s ino=0 size=31027221 mode=-rw-rw-r--, err=<nil>
2018/10/24 16:05:08 DEBUG : /: Attr: 
2018/10/24 16:05:08 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:08 DEBUG : : Statfs: 
2018/10/24 16:05:08 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:08 DEBUG : : Statfs: 
2018/10/24 16:05:08 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:09 DEBUG : : Statfs: 
2018/10/24 16:05:09 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:10 DEBUG : : Statfs: 
2018/10/24 16:05:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:11 DEBUG : : Statfs: 
2018/10/24 16:05:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:12 DEBUG : : Statfs: 
2018/10/24 16:05:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:13 DEBUG : : Statfs: 
2018/10/24 16:05:13 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:14 DEBUG : : Statfs: 
2018/10/24 16:05:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:15 DEBUG : : Statfs: 
2018/10/24 16:05:15 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:16 DEBUG : : Statfs: 
2018/10/24 16:05:16 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:17 DEBUG : : Statfs: 
2018/10/24 16:05:17 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:18 DEBUG : : Statfs: 
2018/10/24 16:05:18 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:19 DEBUG : : Statfs: 
2018/10/24 16:05:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:20 DEBUG : : Statfs: 
2018/10/24 16:05:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:21 DEBUG : : Statfs: 
2018/10/24 16:05:21 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:22 DEBUG : : Statfs: 
2018/10/24 16:05:22 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:23 DEBUG : : Statfs: 
2018/10/24 16:05:23 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>

Scanning via Radarr:

018/10/24 16:05:23 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:23 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:23 DEBUG : Movies/: Attr: 
2018/10/24 16:05:23 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:23 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:23 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:23 DEBUG : Movies/: Attr: 
2018/10/24 16:05:23 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:23 DEBUG : Movies/: Lookup: name="Leon The Professional (1994)"
2018/10/24 16:05:24 DEBUG : : Statfs: 
2018/10/24 16:05:24 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: >Lookup: node=Movies/Leon The Professional (1994)/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/Leon The Professional (1994)/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/Leon The Professional (1994)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Lookup: name="Life Is Beautiful (1997)"
2018/10/24 16:05:25 DEBUG : Movies/: >Lookup: node=Movies/Life Is Beautiful (1997)/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/Life Is Beautiful (1997)/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/Life Is Beautiful (1997)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:25 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Attr: 
2018/10/24 16:05:25 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:25 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:25 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Lookup: name="Leon The Professional (1994)"
2018/10/24 16:05:25 DEBUG : Movies/: >Lookup: node=Movies/Leon The Professional (1994)/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/Leon The Professional (1994)/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/Leon The Professional (1994)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Lookup: name="Life Is Beautiful (1997)"
2018/10/24 16:05:25 DEBUG : Movies/: >Lookup: node=Movies/Life Is Beautiful (1997)/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/Life Is Beautiful (1997)/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/Life Is Beautiful (1997)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:25 DEBUG : : Statfs: 
2018/10/24 16:05:25 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/: Lookup: name="Life (2017)"
2018/10/24 16:05:25 DEBUG : Movies/: >Lookup: node=Movies/Life (2017)/, err=<nil>
2018/10/24 16:05:25 DEBUG : Movies/Life (2017)/: Attr: 
2018/10/24 16:05:25 DEBUG : Movies/Life (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="mother! (2017)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/mother! (2017)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/mother! (2017)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/mother! (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Novitiate (2017)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Novitiate (2017)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Novitiate (2017)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Novitiate (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Loving Pablo (2017)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Loving Pablo (2017)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Loving Pablo (2017)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Loving Pablo (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : : Statfs: 
2018/10/24 16:05:26 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:26 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:26 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:26 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Moon (2009)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Moon (2009)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Moon (2009)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Moon (2009)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Now You See Me (2013)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Now You See Me (2013)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Now You See Me (2013)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Now You See Me (2013)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="One Flew Over the Cuckoo's Nest (1975)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/One Flew Over the Cuckoo's Nest (1975)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/One Flew Over the Cuckoo's Nest (1975)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/One Flew Over the Cuckoo's Nest (1975)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Mulholland Drive (2001)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Mulholland Drive (2001)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Mulholland Drive (2001)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Mulholland Drive (2001)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Once Upon a Time in Hollywood (2019)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Once Upon a Time in Hollywood (2019)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Once Upon a Time in Hollywood (2019)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Once Upon a Time in Hollywood (2019)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Molly's Game (2017)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Molly's Game (2017)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Molly's Game (2017)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Molly's Game (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/: Lookup: name="Mission Impossible - Fallout (2018)"
2018/10/24 16:05:26 DEBUG : Movies/: >Lookup: node=Movies/Mission Impossible - Fallout (2018)/, err=<nil>
2018/10/24 16:05:26 DEBUG : Movies/Mission Impossible - Fallout (2018)/: Attr: 
2018/10/24 16:05:26 DEBUG : Movies/Mission Impossible - Fallout (2018)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:27 DEBUG : Movies/: Lookup: name="Maudie (2017)"
2018/10/24 16:05:27 DEBUG : Movies/: >Lookup: node=Movies/Maudie (2017)/, err=<nil>
2018/10/24 16:05:27 DEBUG : Movies/Maudie (2017)/: Attr: 
2018/10/24 16:05:27 DEBUG : Movies/Maudie (2017)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:27 DEBUG : : Statfs: 
2018/10/24 16:05:27 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:28 DEBUG : : Statfs: 
2018/10/24 16:05:28 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:29 DEBUG : : Statfs: 
2018/10/24 16:05:29 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:30 DEBUG : : Statfs: 
2018/10/24 16:05:30 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:31 DEBUG : : Statfs: 
2018/10/24 16:05:31 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:32 DEBUG : : Statfs: 
2018/10/24 16:05:32 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:33 DEBUG : : Statfs: 
2018/10/24 16:05:33 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:34 DEBUG : : Statfs: 
2018/10/24 16:05:34 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:35 DEBUG : : Statfs: 
2018/10/24 16:05:35 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:36 DEBUG : : Statfs: 
2018/10/24 16:05:36 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:37 DEBUG : : Statfs: 
2018/10/24 16:05:37 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:37 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:37 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:37 DEBUG : Movies/: Attr: 
2018/10/24 16:05:37 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:37 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:05:37 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:05:37 DEBUG : Movies/: Attr: 
2018/10/24 16:05:37 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:05:37 DEBUG : Movies/: ReadDirAll: 
2018/10/24 16:05:37 DEBUG : Movies/: >ReadDirAll: item=177, err=<nil>
2018/10/24 16:05:37 DEBUG : Movies/: Lookup: name="A Fortunate Man (2018)"
2018/10/24 16:05:37 DEBUG : Movies/: >Lookup: node=Movies/A Fortunate Man (2018)/, err=<nil>
2018/10/24 16:05:37 DEBUG : Movies/A Fortunate Man (2018)/: Attr: 
2018/10/24 16:05:37 DEBUG : Movies/A Fortunate Man (2018)/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>

Matching a file:

2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: >Read: read=32768, err=<nil>
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: Read: len=65536, offset=32768
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: >Read: read=65536, err=<nil>
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: Read: len=131072, offset=98304
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: >Read: read=131072, err=<nil>
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: Read: len=131072, offset=229376
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : &{Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv (r)}: >Read: read=131072, err=<nil>
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 2093056 length 1048576 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : &{Movies/Life (2017)/Life.2017.1080p.BluRay.x264-Replica[EtHD].mkv (r)}: >Read: read=1847, err=<nil>
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 3141632 length 1048576 chunkOffset 0 chunkSize 134217728
2018/10/24 16:05:42 DEBUG : : Statfs: 
2018/10/24 16:05:42 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:05:42 DEBUG : Movies/Leon The Professional (1994)/Leon.The.Professional.1994.EXTENDED.2160p.BluRay.REMUX.HEVC.DTS-HD.MA.TrueHD.7.1.Atmos-FGT.mkv: ChunkedReader.Read at 4190208 length 1048576 chunkOffset 0 chunkSize 134217728

Strange log entries that continues by the thousands within minutes

2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95882093
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95882250
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95882407
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95882564
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95882721
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95882878
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883035
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883192
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883349
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883506
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883663
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883820
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: Write: len=157, offset=95883977
2018/10/24 16:11:41 DEBUG : &{rclone.log (w)}: >Write: written=157, err=<nil>

End of the log after 9 min:

2018/10/24 16:13:09 DEBUG : &{rclone.log (w)}: Flush: 
2018/10/24 16:13:10 DEBUG : : Statfs: 
2018/10/24 16:13:10 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:11 DEBUG : : Statfs: 
2018/10/24 16:13:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:12 DEBUG : rclone.log: Size and modification time the same (differ by -40.449µs, within tolerance 1ms)
2018/10/24 16:13:12 DEBUG : &{rclone.log (w)}: >Flush: err=<nil>
2018/10/24 16:13:12 DEBUG : &{rclone.log (w)}: Release: 
2018/10/24 16:13:12 DEBUG : rclone.log: WriteFileHandle.Release nothing to do
2018/10/24 16:13:12 DEBUG : &{rclone.log (w)}: >Release: err=<nil>
2018/10/24 16:13:12 DEBUG : : Statfs: 
2018/10/24 16:13:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:14 DEBUG : /: Remove: name="rclone.log"
2018/10/24 16:13:14 DEBUG : pacer: Rate limited, sleeping for 1.477217128s (1 consecutive low level retries)
2018/10/24 16:13:14 DEBUG : pacer: low level retry 1/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/10/24 16:13:14 DEBUG : pacer: Rate limited, sleeping for 2.909670229s (2 consecutive low level retries)
2018/10/24 16:13:14 DEBUG : pacer: low level retry 2/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/10/24 16:13:14 DEBUG : : Statfs: 
2018/10/24 16:13:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:15 DEBUG : : Statfs: 
2018/10/24 16:13:15 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:15 DEBUG : pacer: Rate limited, sleeping for 4.678326849s (3 consecutive low level retries)
2018/10/24 16:13:15 DEBUG : pacer: low level retry 3/10 (error googleapi: Error 403: Rate Limit Exceeded, rateLimitExceeded)
2018/10/24 16:13:16 DEBUG : : Statfs: 
2018/10/24 16:13:16 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:19 DEBUG : pacer: Resetting sleep to minimum 10ms on success
2018/10/24 16:13:19 DEBUG : /: >Remove: err=<nil>
2018/10/24 16:13:19 DEBUG : /: Attr: 
2018/10/24 16:13:19 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : : Statfs: 
2018/10/24 16:13:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:19 DEBUG : : Statfs: 
2018/10/24 16:13:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:19 DEBUG : /: ReadDirAll: 
2018/10/24 16:13:19 DEBUG : /: >ReadDirAll: item=4, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:13:19 DEBUG : Movies/: Attr: 
2018/10/24 16:13:19 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="Movies"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=Movies/, err=<nil>
2018/10/24 16:13:19 DEBUG : Movies/: Attr: 
2018/10/24 16:13:19 DEBUG : Movies/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="NP"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=NP/, err=<nil>
2018/10/24 16:13:19 DEBUG : NP/: Attr: 
2018/10/24 16:13:19 DEBUG : NP/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="NP"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=NP/, err=<nil>
2018/10/24 16:13:19 DEBUG : NP/: Attr: 
2018/10/24 16:13:19 DEBUG : NP/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="TVShows"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=TVShows/, err=<nil>
2018/10/24 16:13:19 DEBUG : TVShows/: Attr: 
2018/10/24 16:13:19 DEBUG : TVShows/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="TVShows"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=TVShows/, err=<nil>
2018/10/24 16:13:19 DEBUG : TVShows/: Attr: 
2018/10/24 16:13:19 DEBUG : TVShows/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="plex.mp4"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=plex.mp4, err=<nil>
2018/10/24 16:13:19 DEBUG : plex.mp4: Attr: 
2018/10/24 16:13:19 DEBUG : plex.mp4: >Attr: a=valid=1s ino=0 size=31027221 mode=-rw-rw-r--, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Lookup: name="plex.mp4"
2018/10/24 16:13:19 DEBUG : /: >Lookup: node=plex.mp4, err=<nil>
2018/10/24 16:13:19 DEBUG : plex.mp4: Attr: 
2018/10/24 16:13:19 DEBUG : plex.mp4: >Attr: a=valid=1s ino=0 size=31027221 mode=-rw-rw-r--, err=<nil>
2018/10/24 16:13:19 DEBUG : /: Attr: 
2018/10/24 16:13:19 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/10/24 16:13:19 DEBUG : : Statfs: 
2018/10/24 16:13:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:19 DEBUG : : Statfs: 
2018/10/24 16:13:19 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/10/24 16:13:20 DEBUG : : Statfs: 
2018/10/24 16:13:20 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:272201217880 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>

I use Google web authentication during Rclone setup and at the time of the log creation, I were Bulk importing movies to Radarr. At the same time Plex was running and are updating the library on an hourly basis or when it detect changes.

Just to give some context.

Appreciate any input to improve my experience

Can you validate you are impacted by the kernel item or not impacted? If you are impacted, no changes we make would matter much since it’s a kernel bug.

I also turn off analyze in Radarr and Sonarr.

I am impacted by the kernel bug. I’ll upgrade the kernel one of these days to see the impact, but it’s corresponds to the problems I’ve been having

I updated the kernel to Linux 4.15.0-38-generic and it seems that I’m getting better performance. Still not as before with Cache instead of VFS.

But thanks for the tips on the Kernel

In my experience, Cache is slower than VFS.

I’ve scanned roughly 40TB in 2 1/2 days with VFS which is comprised of ~2k Movies and 20k TV shows.

A lot of that depends on your settings though and what you are using.