Slow media start times with mount cache

Qwatuz · June 15, 2018, 6:30pm

Evening folks.

I’ve recently started using rclone cache as read-only and pointing Plex to it with plans to replace Plexdrive.

I’ve noticed the start times are quite random, sometimes they can be <3 seconds and sometimes take 20-30 seconds regardless of direct play / transcode or what bitrate the media is.

For comparison, when running Plexdrive I get consistent start times of <5 seconds no matter the media file.

Does anyone else have similar experiences or do I need to adjust my settings?

Also I have pre-built the cache by running find .

This is what i’m using currently:

/usr/bin/rclone mount cache: /home/user/plexdrive \
   --allow-other \
   --allow-non-empty \
   --dir-cache-time=1m \
   --cache-chunk-size=10M \
   --cache-total-chunk-size=50G \
   --cache-info-age=24h \
   --cache-workers=12 \
   --cache-tmp-upload-path /home/user/.cache3/rclone/upload \
   --cache-tmp-wait-time 1m \
   --cache-db-path /home/user/.config/rclone/cache/ \
   --umask 002 \
   --rc \
   --read-only \
   --log-level DEBUG \
   --syslog

and for my remotes:

[cache]
type = cache
remote = gsuitecache:
plex_url = http://127.0.0.1:32400
plex_username = username
plex_password = plexpw
chunk_size = 10m
info_age = 24h
chunk_total_size = 50G
plex_token = plextoken

[gsuitecache]
type = drive
client_id = clientid
client_secret = clientsecret
scope = drive
root_folder_id = 
service_account_file = 
token = token

Animosity022 · June 15, 2018, 6:58pm

The way the plex integration works, it takes until plex notices you are playing to the file to kick the workers up from 1 to whatever your config is.

With 12 workers, are you seeing any 403/500s in the logs as that seems like it was generate some errors.

Qwatuz · June 15, 2018, 7:13pm

I didn’t see any errors in the logs. I lowered the workers to 5, removed plex intergration and changed from DEBUG to INFO logging and it seemed to speed up the loading times although there are some that take 10-20 seconds.

Out of curiosity, do you have consistent fast load times on videos? Similar cache settings?

Qwatuz · June 29, 2018, 2:00pm

After lots of testing i’ve been unable to reduce the load times.

I’ve tried using

--vfs-read-chunk-size 10M \
--vfs-read-chunk-size-limit 512M \

The full mount is now:

/usr/bin/rclone mount cache:MyMedia/Movies-Remux /mnt/plexdrive \
--allow-other \
--dir-cache-time 48h \
--cache-dir /data/rclone \
--vfs-read-chunk-size 10M \
--vfs-read-chunk-size-limit 512M \
--buffer-size 100M \
--umask 002 \
--read-only \
--rc \
--log-level DEBUG \
--log-file=/home/user/.config/rclone/cache/cache.log

which was taken from Guide to replaceing plexdrive/unionfs with rclone cache

The whole mount has already had find . ran beforehand to populate the cache.

15:47:48 - Clicked Play
15:48:19 - Plex loaded data (Showed total time of video in player)
15:48:25 - Plex started playing video

That resulted in a 37 second start time.

Here’s a DEBUG log of the mount when I try and play a movie that is already scanned into and analysed by Plex.

https://pastebin.com/4uA5x3ta

Also just to mention, I am trying to play the files directly from the mount without using unionfs and this server has been tested with a <5 second Plexdrive start time.

Version of rclone is rclone v1.42-013-g6b424213β.

One thing I can see in the logs and also when I run ls -l in the mount dir are some errors. Could they be from displaying non-english characters, i.e Japanese?

2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name="HEAD"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name="HEAD"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name=".git"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/06/29 15:59:16 DEBUG : /: Lookup: name="HEAD"
2018/06/29 15:59:16 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory

Animosity022 · June 29, 2018, 2:17pm

If you want to use the vfs-read-chunk-size, do not use the caching feature.

Just mount your crypt location and do some testing.

I’m using this now:

/usr/bin/rclone mount gcrypt: /GD --allow-other --dir-cache-time 48h --cache-dir /data/rclone --vfs-read-chunk-size 10M --vfs-read-chunk-size-limit 512M --buffer-size 100M --syslog --umask 002 --rc --log-level INFO

Test with mediainfo a few times and see what your times are:

felix@gemini:/gmedia/Movies$ du -ms "Black Panther (2018).mp4"
43094	Black Panther (2018).mp4
felix@gemini:/gmedia/Movies$ time mediainfo "Black Panther (2018).mp4" | grep blah

real	0m1.540s
user	0m0.044s
sys	0m0.021s
felix@gemini:/gmedia/Movies$ time mediainfo "Black Panther (2018).mp4" | grep blah

real	0m0.042s
user	0m0.030s
sys	0m0.013s
felix@gemini:/gmedia/Movies$ time mediainfo "Black Panther (2018).mp4" | grep blah

real	0m0.041s
user	0m0.030s
sys	0m0.013s
felix@gemini:/gmedia/Movies$ time mediainfo "Black Panther (2018).mp4" | grep blah

real	0m0.044s
user	0m0.019s
sys	0m0.026s

The best I can get that mediainfo on a cached mount for me was always returning 4.5-5 seconds. I’ve tried quite a number of settings to get that number as I was very bored at work the other day.

Qwatuz · June 29, 2018, 3:10pm

Aha thanks for the information.

I just finished setting it up as a direct mount and the load times are just as slow.

mediainfo 0.13s user 0.05s system 0% cpu 31.265 total
mediainfo 0.12s user 0.04s system 0% cpu 42.838 total
mediainfo 0.20s user 0.08s system 0% cpu 1:37.46 total

Around 30 seconds start time with this log

https://pastebin.com/LkLSHtF5

When I play files that have already been played, they will load almost instantly I assume because the chunks are still in the cache:

https://pastebin.com/qjvdRC2j

Is rclone having trouble finding the files?

BinsonBuzz · June 29, 2018, 3:21pm

This is my experience with cache and vfs as well - no difference in load times

Animosity022 · June 29, 2018, 3:31pm

I’m trying to make sure I understand the log files as it looks like you are doing some cache and crypt still?

The mount should be a direct point to GD->Crypt and no cache if you are using VFS.

felix@gemini:/Test/Movies$ time mediainfo “Black Panther (2018).mp4” | grep blah

real 0m2.494s
user 0m0.050s
sys 0m0.040s
felix@gemini:/Test/Movies$
felix@gemini:/Test/Movies$ time mediainfo “Black Panther (2018).mp4” | grep blah

real 0m1.209s
user 0m0.061s
sys 0m0.047s
felix@gemini:/Test/Movies$ time mediainfo “Black Panther (2018).mp4” | grep blah

real 0m1.597s
user 0m0.053s
sys 0m0.042s
felix@gemini:/Test/Movies$ cd
felix@gemini:~$ fusermount -uz /Test

My entire log for a single mediainfo looks like this:

2018/06/29 11:30:26 DEBUG : Movies/Black Panther (2018).mp4: Attr:
2018/06/29 11:30:26 DEBUG : Movies/Black Panther (2018).mp4: >Attr: a=valid=1s ino=0 size=45186687574 mode=-rw-rw-r–, err=
2018/06/29 11:30:26 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=0
2018/06/29 11:30:26 DEBUG : Movies/Black Panther (2018).mp4: ReadFileHandle.seek from 45186687574 to 0 (fs.RangeSeeker)
2018/06/29 11:30:26 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.RangeSeek from 45186687574 to 0 length -1
2018/06/29 11:30:26 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at -1 length 4096 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:26 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.openRange at 0 length 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=131072
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 520192 length 524288 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=262144
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=393216
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 1044480 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=524288
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=655360
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=786432
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=917504
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 2093056 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1048576
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1179648
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1310720
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1441792
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1572864
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1703936
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1835008
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=1966080
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 3141632 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2097152
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2228224
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2359296
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2490368
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2621440
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2752512
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=2883584
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3014656
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 4190208 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3145728
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3276800
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3407872
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3538944
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3670016
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3801088
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=3932160
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4063232
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 5238784 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4194304
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 6287360 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4325376
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4456448
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4587520
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4718592
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4849664
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=4980736
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5111808
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5242880
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5373952
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5505024
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5636096
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5767168
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=5898240
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6029312
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6160384
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 7335936 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6291456
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6422528
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6553600
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6684672
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6815744
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=6946816
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=7077888
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=7208960
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 8384512 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=7340032
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=7471104
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=7602176
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Read: len=131072, offset=7733248
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Read: read=131072, err=
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 9433088 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 10481664 length 1048576 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.Read at 10485760 length 1044480 chunkOffset 0 chunkSize 10485760
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ChunkedReader.openRange at 10485760 length 20971520
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: Attr:
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: >Attr: a=valid=1s ino=0 size=45186687574 mode=-rw-rw-r–, err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Flush:
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: >Flush: err=
2018/06/29 11:30:27 DEBUG : &{Movies/Black Panther (2018).mp4 ®}: Release:
2018/06/29 11:30:27 DEBUG : Movies/Black Panther (2018).mp4: ReadFileHandle.Release closing

It’s pretty damn quick when I’m using VFS.

Are you using any other unionfs/mergerfs or are you doing a direct rclone mount and testing on that?

Qwatuz · June 29, 2018, 3:58pm

I was using VFS with a unionfs I believe but no cache (the remote was called gsuitecache).

I just setup a second server with no unionfs and going direct to VFS rclone mount and the load times are 2-4 seconds.

I’m still not sure what the problem is however. As I have a third server that i’ve been testing out that is direct to rclone mount cache (no union or VFS) that has 20-60 second start times.

Is VFS a suitable replacement for rclone mount cache? How does it handle library scans for new items or API limits?

Animosity022 · June 29, 2018, 4:00pm

With unionfs or mergerfs, you need to use the ‘sync_read’

I use mergerfs so not sure what other defaults unionfs uses, but try passing:

-o sync_read

with your unionfs mount and see if that fixes the unionfs.

Animosity022 · June 29, 2018, 4:01pm

My last 7 days of API hits with vfs, some 403 and 500s are normal and probably more related to my rclone moves.

neik · June 29, 2018, 4:17pm

Just wondering: Were you using cache or vfs during that time period?

In the last couple of days I have been reworking a lot of stuff on my mount and didn’t get a single 403 just a couple of 500. I am using vfs.

Animosity022 · June 29, 2018, 4:20pm

All my Plex/Emby traffic is VFS, but I have been doing some cache testing and VFS testing over the last few days so some hits for that are there as well.

I usually do that on a Test mount and validate timings with mediainfo as a baseline before I try to play anything as for me, that seemed like a good baseline test as if I made that fast, my start and play times would be good.

BinsonBuzz · June 29, 2018, 4:48pm

ok, feeling stupid but happy!!! I’ve just realised when I was testing vfs I was still mounting my cache, not the crypt directly - duh!

My launch times are averaging sub 10s now, sometimes 2-4s which is excellent

ncw · June 30, 2018, 11:35am

Nice!

What are you using for these?

  --vfs-read-chunk-size int            Read the source objects in chunks.
  --vfs-read-chunk-size-limit int      If greater than --vfs-read-chunk-size, double the chunk size after each chunk read, until the limit is reached. -1 is unlimited.

I’d like to change the defaults for the v1.43 release

Animosity022 · June 30, 2018, 11:58am

Those were all based on:

--vfs-read-chunk-size 10M
--vfs-read-chunk-size-limit 100M

Based on more testing, I think that is way too small as it makes quite a lot of calls to get the data for a 4GB file. I think by upping it, it can reduce the churn of calls and still produce a good result.

I’ve upped to:

--vfs-read-chunk-size 64M
--vfs-read-chunk-size-limit 256M

That really seems to be a nice balance between a nice larger chunk size and the ability to grow the chunk limit as playing occurs. My thought process was that when a ffprobe or mediainfo runs against a file, if you can limit the number of calls for data to as few as possible, that would be the sweet spot as I wanted to tune for that as that’s the biggest pain with Plex/Emby when you add files. If that is good, playing should be no problem.

I think @B4dM4n is tuning for torrenting which sounds like a different use case, but would love to hear more feedback on finding a better config for playing media via Plex/Emby.

ncw · June 30, 2018, 5:04pm

Thanks for that. I’m looking for a conservative set of parameters to make the defaults, that works well enough for most people.

@B4dM4n’s settings are

--vfs-read-chunk-size 128M \
--vfs-read-chunk-size-limit 2G \

Do you find having a smaller -limit helps?

Given that the current settings are effectively

--vfs-read-chunk-size ∞
--vfs-read-chunk-size-limit ∞

To err on the cautious side would be to make the -limit quite big.

Animosity022 · June 30, 2018, 6:33pm

I didn’t see any issue with a larger limit and was just testing values.

Two things I’ve noticed in my testing.

If the item is transcoded, this seems to be “greedy” in terms of getting a rather large chunk size as for me, my config buffers up to 600 seconds to the transcode.

I saw it climb from the debug logs and it stopped at the max 2GB on my test mount:

2018/06/30 14:03:37 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ChunkedReader.Read at 3127963648 length 1048576 chunkOffset 2113994752 chunkSize 2147483648
2018/06/30 14:03:37 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ChunkedReader.Read at 3129012224 length 1048576 chunkOffset 2113994752 chunkSize 2147483648
2018/06/30 14:03:37 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ChunkedReader.Read at 3130060800 length 1048576 chunkOffset 2113994752 chunkSize 2147483648
2018/06/30 14:03:37 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ChunkedReader.Read at 3131109376 length 1048576 chunkOffset 2113994752 chunkSize 2147483648

If I used Infuse, which tends to Direct play everything, there is no transcoding so I’m beholden more to the buffer size I set in the mount. If I left the limit at 2GB for vfs-chunks, it would stop at whatever buffer size I configured. 256M buffer gave me 256M chunks, 512M gave me 512M chunks. Finally a 1GB buffer gave me 1GB chunks:

2018/06/30 14:12:42 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ChunkedReader.Read at 1127522304 length 1048576 chunkOffset 1040494592 chunkSize 1073741824

I can see in all cases, it started and worked its way up the chunk size over 8-15 seconds.

So it sounds like if I’d probably want to keep a buffer at an “ok” value 256M or 512M to give me some help on direct plays in case something gets sluggish and for transcodes, it’s really dependent on how Plex is configured. I do 600 seconds personally as that seems like a nice value:

One other thing I can’t seem to figure out. Plex opens and closes a file 4 times before it plays it.

2018/06/30 14:30:47 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ReadFileHandle.Release closing
2018/06/30 14:30:52 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ReadFileHandle.Release closing
2018/06/30 14:31:03 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ReadFileHandle.Release closing
2018/06/30 14:31:03 DEBUG : Radarr_Movies/Dracula (1992)/Dracula (1992).mkv: ReadFileHandle.Release closing

When I do the same with Emby, it just opens and plays. I’m sure there is some setting or something else going on, but I haven’t figure it out yet

Animosity022 · June 30, 2018, 6:58pm

The extra file / open closes was because the file I was trying to play was not analyzed so it has to run a few things before it plays it.

B4dM4n · July 1, 2018, 12:12pm

I notice these additional open’s with Plex as well. Even if the file has been analyzed, Plex will rescan it when the last scan was a while ago.

I’m not using --vfs-read-chunk-size for torrenting. My primary use case is Plex. Torrenting via a rclone mount is probably a bad idea, as the torrent protocol is build around random 64k blocks, which is too small to be handled by a Gdrive remote to be handled.
If the blocks accessed are in order and the Torrent client keeps the file open, there is a chance, that serving torrents would work at a reasonable speed. A cache remote could maybe improve speeds, but if the blocks are random, the chance of hitting a cached block in a large file are minimal.

I think we can set --vfs-read-chunk-size-limit -1, which means infinite growth. This should work for all file sizes. When many chunks are read in a row, the chance is high that the next chunk we be used complete.
I will open a Issue where we can discuss new default values.