30 seconds to start playback - 100mbps download speed

Here's a verbose log of a video playback. MKV file

As you can see - playback starts at 18:18:08 - it stuffs around for about 40 seconds - before it starts playing
https://pastebin.com/0rapsJj7


Here is a verbose log of a music file playback - approx 8MB in size

I request playback of the file at 18:29:53, it doesn't start playing for approx 34 seconds

https://pastebin.com/iK1Hui6R

I could download the entire file quicker than that!


I have a 14ms ping to Google DNS 8.8.8.8 if that helps at all.

@ncw I think this is your cue. I'm not so good at this part yet :sweat_smile:

This is the problem

15 matches for "ReadFileHandle.seek" in buffer: 0rapsJj7.txt
   2277:2019/10/14 18:18:22 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 32768 to 1536032768 (fs.RangeSeeker)
   2286:2019/10/14 18:18:24 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 1536061767 to 61440 (fs.RangeSeeker)
   2298:2019/10/14 18:18:25 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 94208 to 0 (fs.RangeSeeker)
   2448:2019/10/14 18:18:28 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 32768 to 1536032768 (fs.RangeSeeker)
   2457:2019/10/14 18:18:29 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 1536061767 to 61440 (fs.RangeSeeker)
   2471:2019/10/14 18:18:30 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 94208 to 0 (fs.RangeSeeker)
   2518:2019/10/14 18:18:33 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 32768 to 1536032768 (fs.RangeSeeker)
   2587:2019/10/14 18:18:34 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 1536061767 to 61440 (fs.RangeSeeker)
   2779:2019/10/14 18:18:35 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 94208 to 0 (fs.RangeSeeker)
   2880:2019/10/14 18:18:37 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 32768 to 1536032768 (fs.RangeSeeker)
   2889:2019/10/14 18:18:38 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 1536061767 to 61440 (fs.RangeSeeker)
   2907:2019/10/14 18:18:40 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 94208 to 0 (fs.RangeSeeker)
   2919:2019/10/14 18:18:42 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 131072 to 1536043449 (fs.RangeSeeker)
   2929:2019/10/14 18:18:43 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 1536061767 to 1536021799 (fs.RangeSeeker)
   2938:2019/10/14 18:18:44 DEBUG : TV/24/Season 1/24 - S01E02 - 1-00 A.M. - 2-00 A.M.mkv: ReadFileHandle.seek from 1536061767 to 5601 (fs.RangeSeeker)

There are 15 seeks there... Looking at the timestamps these take about 2 seconds which explains where the 30 seconds delay is coming from.

A seek for rclone means closing the current stream and re-opening a new one at a new position. That seems to take google drive 1-2 seconds.

You could try --vfs-cache-mode full which will do exactly that, download the entire file first... Though if you've got something like plex scanning your media that may not be ideal as it will fill your disk up!

@ncw in your experience - is this behaviour more likely to be a problem in the player application, or a problem of media-formats not being linear?

I know there are some videoformats that tend to mess up, but OP says he also has the exact same issue with a regular old m3, and that should definitely be linear and not need any skipping round... Just trying to wrap my head around the details of exactly what the root cause is for this.

What media formats are non linear? I've never heard of that.

It's how the player / application works that is the issue.

It's speculation on my part - but while most simple containers are just audio and video tracks being muxed together, some containers also contain lots of other stuff - like MKVs. They have all sorts inner metadata, chaperinfo, even DVD-like menus and such in some cases. And how that info is structured in the file I just don't know. I would assume they would put those things all at the front of the file - but if that wasn't the case then rclone might be forced to jump around a lot.

While I have no problem playing the vast majority of videos via VLC from Gdrive, I do on occasion see a handful of files here and there that just refuse to play well. Taking both a long time to start and consistently stuttering. They are usually not even high bitrate. That is of course using the exact same VLC player. So this just leads me to believe that the formatting (or more likely container type to be spesific) plays some sort of role in this.

Seeking around a file is ok.

Open and closing a file is not as that's very slow.

If VLC opens and closes, the file, it's going to be slow as those operations take some time.

Rather than speculating, just run a debug and you can see. It's easy rather than just guessing and putting out incorrect information.

Yea, but running the debug log can only tell us that it is happening - not why it is happening (which is the even more interesting question - because ideally you'll want to solve it). Probably something you'd have to log in VLC to actually get an answer to...

It shows you why as you can see the open and closes being issued by the application. What more are you looking for? Many applications aren't really coded in such a way that they are expecting slow storage such as cloud.

The VLC code is there so you can see the system calls they make:

I forgot to analyse this one...

It seems to seek 4 times for each file, however it seems to be doing that to all the files in the directory, not just the one you are playing.

It can be the media player. It can also be Explorer which loves opening every file and reading thumbnails bitrates etc.

1 Like

I really think it's what @ncw just said above. I used to have this issue, and I went ahead and disabled all the Windows Explorer media info stuff, time stamps, etc. It's been great ever since, using MPC-HC. I watched a 75GB file last night, and it took 12 seconds to open. Seeks are instantaneous.

Try this on the entire mounted drive:

image

Tha is everyone for the help and input. I really appreciate it.

There seems to be a focus on the client being at fault here- but this behaviour occurs with every client I've tried. VLC, MPC and Plex.

I know for certain Plex doesn't open and close files multiple times before playing.

I'm almost certain I've already done this as navigating through the file directory was painfully slow, but I'll have another look.

Yeah, if Plex does it, too, then it's probably something else. All my Plex clients start playback very quickly.

Gotta be careful as it does not occur with all Plex Clients as they are many. I can only speak to Apple TVs/ Plex Media Player and NVidia Shields, which do not rapidly open and close files.

I just find it weird how from my own experience VLC plays most of them fine - then on some files (of clearly the same source) just struggle.

If it would be interesting I could share an example of such a file - because one of my old shadowplay video sets behave problematically like this (I think captured on my old GTX 970) and these are "only" 100-200MB test clips without copyright or privacy issues.

Meanwhile I play some really tough high-biterate 4K videos super-smooth... and that just makes me very curious as to what the difference is...

Sorry yes- when I'm testing I use the web client on the server itself.

It can't be my internet connection - as I can stream these same files, Direct Play in Plex, from the other side of the globe, and they play within 5 seconds.

But when I mount the same files locally on my Windows machine, they take 40 seconds to play.

Is the Web Client direct playing? Are you setting quality to maximum on the Web Client?

Yes, 100% direct play, original quality.

Plex exhibits the same playback times as VLC and MPC so I really don't think the issue is client related.

When I try and change the entire mounted drive to "Documents" and press apply it doesn't save the setting. Opening up Properties again, it goes back to "General Items"

Edit// actually looks like "Documents" was already applied recursively. When I go to one of the TV folders within the directory, it is already set to "Documents"