Google Drive access slow via Plex Client but very fast with everything else

OneADay · March 19, 2019, 9:43pm

Hi,

I have been experimenting with Rclone to mount my encrypted Google Drive and use that to stream Plex content. For 1080p movies and lower everything works well; however 4k movies with high bitrate buffers (>25Mbps) every few seconds so it’s fairly unusable. The weird thing is that if I rsync a file out of the mount then the speed is almost 10 times faster. I’m running rclone 1.46. Here’s what the config file looks like:

[gdrive]
type = drive
client_id = xxxxx
client_secret = xxxxx
scope = drive
root_folder_id = 
service_account_file = 
token = {"access_token":"xxxx","token_type":"Bearer","refresh_token":"xxxx","expiry":"2019-03-18T22:44:45.961335765-04:00"}

[gcrypt]
type = crypt
remote = gdrive:/encrypt
filename_encryption = standard
directory_name_encryption = true
password = xxxx
password2 = xxxx

And the options I use with rclone mount look like this:

--allow-other
--buffer-size 1G
--dir-cache-time 1m
--drive-chunk-size 32M
--fast-list
--umask 002
--vfs-read-chunk-size 128M
--vfs-read-chunk-size-limit off
--log-level DEBUG
--vfs-cache-max-age 24h0m0s
--vfs-cache-mode writes

Here’s two log files showing around 5 minutes of transfer for Plex and for rsync: https://drive.google.com/open?id=1qiQq7BT11zCsl9elNzpzuJa47XVx7YyE (apologies for not using Pastebin, the log file size is much too large for the free service).

I’ve tried to isolate the issue to make sure it’s not something else in my stack that is causing this issue, for example:

Streaming the same file from local storage is fine - so it excluded the possibility of local network throughput bottleneck.
As you can see from the logs, rsync a file from the mount is very fast (it gets to 200Mbps with no issue) - much more than needed to stream that file. That excludes the possibility of Internet throughput bottleneck.
I’ve also tried using --drive-v2-download-min-size 0 to see if it’s a peering issue with the v3 API, but it doesn’t improve the situation.
I’ve also made sure that the rsync result is not due to rclone already caching the same file. I’ve tried it with multiple different files with the same result.

From all the debugging I’ve done it seems that the Plex Client (I use the nVidia Shield client) may be the issue, but I can’t find anything suspicious (like repeatedly opening/closing file handles) in the log that would explain this behavior.

If you guys have any suggestion, I’m all ears. Thanks in advance!

Animosity022 · March 20, 2019, 12:00am

Few things.

fast-list doesn’t do anything on a mount and can be removed.
dir-cache-time 1m really does nothing for and super slows things down. You should make that something like 48 hours or higher.

You seem to be running a dev version? You should just grab the latest stable and use that.

Did you stop and start it many times or just hit play once?

egrep  'ONLY|Flush' rclone.playback.log
rclone_1          | 2019/03/18 23:00:59 DEBUG : movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv: Open: flags=O_RDONLY
rclone_1          | 2019/03/18 23:00:59 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: Flush:
rclone_1          | 2019/03/18 23:00:59 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: >Flush: err=<nil>
rclone_1          | 2019/03/18 23:00:59 DEBUG : movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv: Open: flags=O_RDONLY
rclone_1          | 2019/03/18 23:00:59 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: Flush:
rclone_1          | 2019/03/18 23:00:59 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: >Flush: err=<nil>
rclone_1          | 2019/03/18 23:00:59 DEBUG : movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv: Open: flags=O_RDONLY
rclone_1          | 2019/03/18 23:01:00 DEBUG : movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv: Open: flags=O_RDONLY
rclone_1          | 2019/03/18 23:01:00 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: Flush:
rclone_1          | 2019/03/18 23:01:00 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: >Flush: err=<nil>
rclone_1          | 2019/03/18 23:01:01 DEBUG : movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv: Open: flags=O_RDONLY
rclone_1          | 2019/03/18 23:01:01 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: Flush:
rclone_1          | 2019/03/18 23:01:01 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: >Flush: err=<nil>
rclone_1          | 2019/03/18 23:06:17 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: Flush:
rclone_1          | 2019/03/18 23:06:17 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: >Flush: err=<nil>
rclone_1          | 2019/03/18 23:06:18 DEBUG : movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv: Open: flags=O_RDONLY
rclone_1          | 2019/03/18 23:06:18 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: Flush:
rclone_1          | 2019/03/18 23:06:18 DEBUG : &{movies/Spider-Man Into the Spider-Verse (2018)/Spider-Man.Into.the.Spider-Verse.2018.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.mkv (r)}: >Flush: err=<nil>

The file keeps opening and closing which could be the cause of your delay. You can perhaps turn off Direct Play and let it Direct Stream as that is a client thing if you are just hitting play and it isn’t working.

OneADay · March 20, 2019, 4:28am

Thanks for your response @Animosity022, I appreciate it!

Good to know about fast-list not doing anything. I believe I used dir-cache-time because the client uploading the content is different vs the client consuming the content, so I set it to 1m in order for the consuming client to see the uploaded file sooner. Is that how it’s supposed to work?

I was running the dev version when I captured the log. I’ve tried the latest stable as well and it didn’t make a difference.

I did not stop and start, I just let the stream run for about 5 minutes so that I can compare to the rsync process.

I’m going to try the Direct Stream option and see if it helps. From a quick glance I can’t find it on the Shield though, maybe it’s hidden in some deep menu.

EDIT: So another thing is that I’ve run this set up for a while now and it used to work fine. I thought it may be because this movie is higher bit rate than my old ones, but now my old ones also buffer to no end. I looked on the nVidia forum and it seems that other people are running into the same issue after a firmware upgrade, so maybe they changed something in the back end which is causing this issue.

Animosity022 · March 20, 2019, 11:30am

You can make dir-cache-time as much as you want. Drive polling handles changes that are detected and will invalidate the cache if a change is detected.

Having a low dir-cache-time just makes for a lot of wasted hits and slows down performance immensely since it has nothing cached.

The goal with the latest stable is you have a known state as a DEV version, you aren’t sure what was being fixed or added in there or what else might be working or not working.

OneADay · March 21, 2019, 3:32am

I took out the dir-cache-time and it works exactly as you described - thank you for the tip.

I usually run the stable version but was just jumping to the DEV version to see if it helps - I’m a developer so I do know the pros/cons of running program at the tip of the repository.

Back to the issue, I kinda side stepped it and use a DLNA client to play the file, and it’s working fine now with no stutter whatsoever. This is definitely a bug with the Plex Client/Shield combination, and hopefully they’ll get it fixed soon so I don’t have to use workarounds like these.

Thank you for your help debugging this and the performance tips @Animosity022!

Animosity022 · March 21, 2019, 11:22am

I wouldn’t take it out as I’d adjust it to 24h / 48h / 72h / 96h. The default is just 5 minutes.

system · June 19, 2019, 11:22am

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