Read ahead runs independently from max size.
Max-age/Max size only gets called based on your polling interval.
That's why I asked above to re-create one file and share a debug log and you can see 100% what is going on and if things make sense.
1 Like
I made some tests and I now have a better idea of how vfs-cache works with read-ahead.
I am particularly intrigued by the following behaviour, which I document below, and attach a log file to that effect. I did not monitor the log for this as I am not sure what to look for (plus, it's huge), but I monitored this through what's actually written on the cache disk.
Vfs cache set to 6G total, 5G read ahead. Max-age was set to 48h.
Started playing one file at 09:32.
At about 09:34 read-ahead cache reached max-size, but movie was not anywhere near that point. Cache was emptied and read-ahead started again.
At about 09:37 the same thing happened again, max-size reached, cache emptied and started again (but the movie was nowhere near the end of the read-ahead data).
Is this expected (or desired) behaviour? I would think it is wasteful to empty a perfectly good read-ahead cache and start again, the file then gets downloaded mutliple times.
Also, this goes against what the documentation says, that open files don't get evicted from cache. Clearly in this case it does as the movie is still playing, hence file still open.
Based on these two points, is this perhaps a bug and not intended behaviour?
This seems to ignore the max-age value too, as the currently playing file is evicted without consideration as to the max-age (althought that's maybe to be expected).
My expected behaviour would have been to stop read-ahead when max-size is reached, then wait for the movie to play until the cache has been played fully. Then it can evict and start reading-ahead the next part.
I also found that if I have watched one file, and it is still resident in vfs-cache as the max-age hasn't been reached, then if I play a new file, the new file gets read-ahead, and when max-size is reached, the old file is evicted, even if max-age hasn't been reached. I think that makes sense, but perhaps the max-age documentation should be updated to reflect this.
I will try to sit and write what I think the documentation should look like based on these findings.
Log:
https://1drv.ms/u/s!AprRBz9GT1pHlspuVixDmvSMcwGeLQ?e=WD9FL0
1 Like
Your key bit to correlate as I don't know what you did playing it or what.
If you are just playing it, you need to understand when you clicked play and when you stopped based on the logs.
I look for open and closes as that directly impacts read ahead. If the file is closed, you won't read ahead.
I do a quick egrep like
egrep 'OpenReadOnly|Flush' rclone_idrive.log
2024/02/29 09:32:47 DEBUG : Movies/2010 - 2019/movie.mkv: Open: flags=OpenReadOnly
2024/02/29 09:32:53 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: Flush:
2024/02/29 09:32:53 DEBUG : Movies/2010 - 2019/movie.mkv(0xc001cd6180): RWFileHandle.Flush
2024/02/29 09:32:53 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: >Flush: err=<nil>
2024/02/29 09:32:53 DEBUG : Movies/2010 - 2019/movie.mkv: Open: flags=OpenReadOnly
2024/02/29 09:38:41 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: Flush:
2024/02/29 09:38:41 DEBUG : Movies/2010 - 2019/movie.mkv(0xc0002e0b40): RWFileHandle.Flush
2024/02/29 09:38:41 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: >Flush: err=<nil>
So you want to line that up with your logs, if you hit play at say 9:32 in the logs, Plex does a quick analyze before playing generally so you get an open and close. Emby looks to do something similiar.
And then playback happens (guessing) from the second open and continues until you stop.
2024/02/29 09:32:53 DEBUG : Movies/2010 - 2019/movie.mkv: Open: flags=OpenReadOnly
2024/02/29 09:38:41 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: Flush:
2024/02/29 09:38:41 DEBUG : Movies/2010 - 2019/movie.mkv(0xc0002e0b40): RWFileHandle.Flush
2024/02/29 09:38:41 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: >Flush: err=<nil>
Did you play for 6 minutes? If so, good, then read ahead is doing what you'd expect.
max read ahead and max size do not operate together. max size is used for polling only and has no relation / correlation to max read ahead.
If you have a file open and it will not be evicted. If the logs are you 6 minutes of playback with direct play for Emby, you won't get the file removed so nothing would happen when max size is hit as it is in use and won't be evicted. This is independent of any settings and read ahead just influences how much more a file is read.
The only time read ahead really would come into play is when a file isn't in the cache and you are reading seuqentially in a file.
Most of your log is files in cache so read ahead doesn't matter minus these false chunks.
grep present rclone_idrive.log | grep -v true
2024/02/29 09:32:47 DEBUG : vfs cache: looking for range={Pos:0 Size:65536} in [{Pos:5468512256 Size:446689280}] - present false
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:26745786368 Size:8926} in [{Pos:0 Size:2093056} {Pos:5468512256 Size:446689280}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:26744856576 Size:36864} in [{Pos:0 Size:433057792} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:26744958976 Size:131072} in [{Pos:0 Size:445636608} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:126976} {Pos:26745786368 Size:8926}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:26745090048 Size:131072} in [{Pos:0 Size:445636608} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:126976} {Pos:26745786368 Size:8926}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:26745221120 Size:131072} in [{Pos:0 Size:446685184} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:258048} {Pos:26745786368 Size:8926}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:3462971392 Size:36864} in [{Pos:0 Size:454025216} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:938718}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:3463008256 Size:131072} in [{Pos:0 Size:474996736} {Pos:3462971392 Size:61440} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:938718}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:3463139328 Size:131072} in [{Pos:0 Size:474996736} {Pos:3462971392 Size:258048} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:938718}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:3463270400 Size:131072} in [{Pos:0 Size:474996736} {Pos:3462971392 Size:258048} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:938718}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:3463401472 Size:131072} in [{Pos:0 Size:474996736} {Pos:3462971392 Size:520192} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:938718}] - present false
2024/02/29 09:32:53 DEBUG : vfs cache: looking for range={Pos:3463532544 Size:131072} in [{Pos:0 Size:474996736} {Pos:3462971392 Size:520192} {Pos:5468512256 Size:446689280} {Pos:26744856576 Size:938718}] - present false
2024/02/29 09:34:36 DEBUG : vfs cache: looking for range={Pos:4305408000 Size:131072} in [] - present false
2024/02/29 09:34:36 DEBUG : vfs cache: looking for range={Pos:4305539072 Size:131072} in [] - present false
2024/02/29 09:37:35 DEBUG : vfs cache: looking for range={Pos:5883777024 Size:131072} in [] - present false
2024/02/29 09:37:35 DEBUG : vfs cache: looking for range={Pos:5883908096 Size:131072} in [] - present false
It's tricky as to really get the benefit of read ahead, it would mean something is not cached/played before and it's populating the cache. To really do the a good test, you'd want to dump the cache and ensure everything is not present and validate what you want to happen.
Testing with files already in the cache makes a lot of this moot in terms of use.
Ok, I understand that for a better analysis I need to know the second I pressed play and the second I stopped it.
Yes that sounds about right.
But...
Well, it did and it does get evicted, every single time.
Maybe the logs don't show this? But the disk usage does. Disk usage goes up and up and up, until about 6.4GB, and then it drops down to kilobytes and starts going up again, while the file is playing (it absolutely did not stop playing when this happened). And it's happened every time I tested it.
Now, could the file be closing while I am watching it?
Could it be that, the file on the remote is open while reading-ahead, then when read-ahead goes to max-size it stops reading the file on the remote, and the file on the remote closes? Then because that closes, it evicts the playing file from the cache, opens the remote file again and starts reading-ahead again?
I am just conjecturing here.
What I do know for a fact is the disk usage goes up to just above max-size setting, then goes to practically zero and starts going up again, while the file is still playing and never stopping.
Well yes, every test I am starting is with the cache empty, the file I am playing is not present.
That's exactly what I am doing.
The logs disagree though as the present true means it's already on disk and it was not cleaned out.
grep "present" rclone_idrive.log | grep true| head -10
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:65536 Size:131072} in [{Pos:0 Size:27258880} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:196608 Size:131072} in [{Pos:0 Size:28307456} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:327680 Size:131072} in [{Pos:0 Size:33550336} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:458752 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:589824 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:720896 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:851968 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:983040 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:1114112 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
2024/02/29 09:32:49 DEBUG : vfs cache: looking for range={Pos:1245184 Size:131072} in [{Pos:0 Size:34598912} {Pos:5468512256 Size:446689280} {Pos:26745786368 Size:8926}] - present true
You'd see a present false if it has to get the data from the remote.
That's actually what I've seen before but @kapitainsky said it wouldn't as it in use. I'm back on my stance it does remove it from the logs. I wasn't sure if something changed along the way to make my old statement not true.
egrep 'free|OpenReadOnly|Flush' rclone_idrive.log
2024/02/29 00:19:45 DEBUG : vfs cache RemoveNotInUse (maxAge=3596400000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:30:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:31:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:32:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:32:47 DEBUG : Movies/2010 - 2019/movie.mkv: Open: flags=OpenReadOnly
2024/02/29 09:32:53 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: Flush:
2024/02/29 09:32:53 DEBUG : Movies/2010 - 2019/movie.mkv(0xc001cd6180): RWFileHandle.Flush
2024/02/29 09:32:53 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: >Flush: err=<nil>
2024/02/29 09:32:53 DEBUG : Movies/2010 - 2019/movie.mkv: Open: flags=OpenReadOnly
2024/02/29 09:33:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:34:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:34:36 INFO : vfs cache purgeClean item.Reset Movies/2010 - 2019/movie.mkv: Item reset completed, freed 7221613278 bytes
2024/02/29 09:35:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:36:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:37:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:37:35 INFO : vfs cache purgeClean item.Reset Movies/2010 - 2019/movie.mkv: Item reset completed, freed 6964637696 bytes
2024/02/29 09:38:35 DEBUG : vfs cache RemoveNotInUse (maxAge=172800000000000, emptyOnly=false): item Movies/2010 - 2019/movie.mkv not removed, freed 0 bytes
2024/02/29 09:38:41 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: Flush:
2024/02/29 09:38:41 DEBUG : Movies/2010 - 2019/movie.mkv(0xc0002e0b40): RWFileHandle.Flush
2024/02/29 09:38:41 DEBUG : &{Movies/2010 - 2019/movie.mkv (rw)}: >Flush: err=<nil>
That gives a good indication the file is open and freed up from space and the sparse file is recreated, which is what I said a number of posts above.
^^^^
So the logs confirm my statement and your statement. Go data!
When I was running from the cloud, the best method I found for streaming was to have a huge max age, whatever your reasonable max cache size is and let rclone do it's thing.
I used a 2TB SSD and made my age 9999h and I have 2 750GB max size cache setups as I had 2 mounts. Rclone cleans the oldest not accessed files first when size hits and it's easy. I'm generally for the least configuration to meet my goal as the less flags, the less things that can break.
1 Like
Correct, it seems the first time I played it some of it was still in cache. However, the behaviour remains the same.
Right, so it evicts the sparse file even though it is open.
But 'cache expiration', in my understanding, means time expiration, as in max-age reached... or not? I think this was a point of misunderstanding. The max-age hasn't been reached, so it hasn't expired. The max-size has been reached.
And the docs say that open files do not get evicted, which according to all these findings is not true, at least for this scenario.
I understand it now a bit more.
It seems the logic is to evict the file because it still wants to keep some of the already-played file in cache and it can't as the cache is full.
However, the logic could be improved. If the file has been read-ahead to a huge extent, the play progress just moves forward.
If I am currently on timestamp 5m00s (for example), and I have 1min cached behind me and 15 mins read-ahead and the cache is full, the file should not be evicted; after 5 minutes I'll have 6 minutes behind me and still 10 minutes read-ahead, and so on, so why evict the file if there is so much read-ahead data still on disk, and the already-played file data is basically increasing anyway as playback goes on?
Ideally it should only evict the file when playback reaches the end of the current read-ahead.
The problem with this is 'its thing' is to read-ahead, then evict and re-download from the current playback point, which results in the majority of the file being downloaded multiple times while playing. This may well result in more issues than what it's trying to solve (e.g. with all these re-downloads the remote might apply throttling earlier than it otherwise would, or random remote slowness issues will inevitably come up more often than they would otherwise).
My aim is to prevent remote streaming glitches from making a movie freeze, so I need the cache to iron out such issues.
Cloud streaming has cost limitations, so my best idea for now is to have a cache drive that is a bit bigger than the largest movie I currently have, with a 48h max-age (no need for files to linger there longer than that). Read-ahead is set to 2GB below
This way, any movie I play will be able to be fully read-ahead and not be constantly evicted every time it hits the max-size. Then if I play a new movie right after the previous one, the previous one will be evicted and new one read-ahead etc. Costs a bit more than I originally would have liked, but I think this will guarantee a smooth experience.
This gets a bit confusing as I think you are combining two sections of the docs. If you are just using size, which is what I've been suggesting, you see the open file portion.
If using --vfs-cache-max-size or --vfs-cache-min-free-size note that the cache may exceed these quotas for two reasons. Firstly because it is only checked every --vfs-cache-poll-interval. Secondly because open files cannot be evicted from the cache. When --vfs-cache-max-size or --vfs-cache-min-free-size is exceeded, rclone will attempt to evict the least accessed files from the cache first. rclone will start with files that haven't been accessed for the longest. This cache flushing strategy is efficient and more relevant files are likely to remain cached.
But when you add age to it, which I think is the confusing point, you get files past the age.
The --vfs-cache-max-age will evict files from the cache after the set time since last access has passed. The default value of 1 hour will start evicting files from cache that haven't been accessed for 1 hour.
So files are not being evicted one the size part, but the age part, which doesn't care about open so there is some 'right' from eveyrone here.
That's where I think I'm not communicating effectively. If that's your goal, a huge max age and the proper size does that. Anything in use stays based on the last access time so only the oldest stuff is evicted first specifically meeting your request here. Your setup with age and size actually does specifically what you don't want it to do by redownloading things since the age quickly times out.
I think 48 hours makes little sense either as your size is fixed, no? Why evict anything on age? If Joe plays something Monday and Bob plays the same thing Friday, it can all be from cache as you've already allocated the size, why not leave it there? What's the concern with a large cache time as that benefits anyone streaming the same things. If you let size drive, you'll always have the 'newest' played stuff in the cache.
I used a $100 SSD for my cache which was way overkill, but even a larger spinning drive would work great unless you plan to stream like a pleothra of concurrent streams.
1 Like
Possibly, but there may be scope to improve them.
For example:
Here, reading this, I understand that an open file cannot be evicted from the cache even if max-size is reached. Do I understand it right?
If I do, this statement is wrong, because here I have an open file, video playing, and it is evicted from the cache when max-size is reached.
The rest of the text from that particular paragraph is not relevant as, at this point, we are only talking about there being one single file in the cache.
Ok, but my max-age is never reached in my case, so why would my file get evicted due to max-age?
Again, just to note that it's not [evicting and] redownloading things because the age times out, but because the size is exceeded.
Yes, that is a valid point and a very helpful contribution to my internal musings regarding the best max-age setup.
Why 48h, why evict? I only have very, very few friends other than myself who might stream from this server, and they have their own servers too, so on the balance of probabilities it is highly unlikely we'll be streaming the same thing within any given timespan (although it may well happen with episodes of new series). I also want to maybe use this cache volume for other purposes, and evicting stale files every so often seems more efficient than manually having to delete them before I can use the volume for other jobs.
I realise that my earlier descriptions did not convey my set up - the cache volume is a cloud volume, as is the server, there is no local server or storage. As such, every GB added to the cache volume costs extra money, which of course I'd like to avoid if possible, so my goal here is to have the minimum viable setup to be able to stream the largest movie I have unimpeded.
I can't confirm that as I believe you are correct, but the log is a snippet so I can't validate your statement with the data. Worse case, the docs need some updating based on changes perhaps. I really don't use rclone so my in depth testing has been from a number of versions back since I moved all local so while I feel I was 'correct', that might change.
Ah, that makes more sense now.
It does sound like some additional testing and log validation and perhaps someone else chiming in on the caching as I have been very wrong before and I'm sure I'll be wrong again sometime 
so having another set of eyes here is always helpful.
I think it's a good set of information so far as we need to just validate bits of this and update documentation as you've gotten a number of findings/doc adjustments I think so far.
1 Like
The log is complete in the sense that this is all I have from when I played the file and saw it fill up the cache, be deleted and fill it up again etc.
If this information is not in the debug log, is there any other way to 'prove' this behaviour, other than perhaps screengrabbing my terminal while tracking disk usage of the cached sparse file (this shows unambiguously that this is what is happening and the file is being evicted when max-size is hit, with no relation to max-age)?
And given this behaviour, should I perhaps open an issue on GitHub?
I understand that his behaviour is indeed what is expected and desired if you only use cache as a means to store the already-played portions of a file, to rewind or rewatch, and that rclone follows the same logic if you are using read-ahead; so I think this is an unintended consequence of the normal cache behaviour for a particular scenario, that could be improved if there was some additional logic to handle max-size actions differently if read-ahead is larger than the cached portion of the file that's already been played.
Not nitpicking, but it's not complete. It's a snippet of a log. I can't see any of your flags or what you mounted with. It's a boolean type question here, either the log is complete (all of it) or not complete (part of the log). You've shared part of the log and only the part with the playback.
Sure, but given the immense backlog unless ncw gets an itch to fix it, nothing is really majorly probelmatic here so it may sit for quite a bit unless you have a real need in which case you can sponsor or it have someone submit a PR for what you want or do it yourself. Edge case, but not debating that it's important for you.
1 Like
Ok, I see your point. What would make it complete? The log is continuous, the last mount may have happened days ago (but I can give the mount options here, see below).
When I extracted this part of the log, I realised that I hadn't set up logrotate for it (I set a different log file for each mount), so I ended up with a log file that's 1.8GB. Where should the paste start and end to be complete?
Mount command:
ExecStart=/usr/bin/rclone mount \
--config=/home/dinosm/.config/rclone/rclone.conf \
--cache-dir /mnt/vfscache/ \
--vfs-cache-mode full \
--vfs-cache-max-age 48h \
--vfs-cache-max-size 142G \
--vfs-fast-fingerprint \
--tpslimit 10 \
--tpslimit-burst 15 \
--vfs-refresh \
--vfs-read-ahead 80G \
--no-checksum \
--no-modtime \
--s3-disable-checksum \
--allow-other \
--user-agent "ISV|rclone.org|rclone/v1.65.2" \
--log-file=/home/dinosm/log/rclone_idrive.log \
--log-level DEBUG \
idriveenc: /home/dinosm/media/iDrive
EDIT:
Of course, that's perfectly understandable.
I like the idea about sponsoring it (I mean, maybe it's unaffordable, but sounds like a good idea to look into), do I ask ncw about it?
I think it's good at this point as you given enough. I was just trying to correlate the max age and I wasn't sure what yours was set at as I thought it was short, but it's 48 hours.
At the end of day, my time is just volunteer so I'm not sure either. I believe you can just send a note to Nick or just use sales@rclone.com I'd imagine.
1 Like
This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.