Testing for new vfs cache mode features

I'm in the process of completing the changes to the vfs cache

This will have these 3 major new features (along with a host of bug fixes!)

  • --vfs-cache-mode full which will only download the parts of the file you need
    • I envision this will become the preferred way of using the vfs cache
  • --vfs-cache-mode writes will do delayed writeback of files
    • this will help with explorer lockups on windows
    • this will help with downloads and renames in quick sucession (eg downloading from a web browser)
  • rclone will pick up in progress or failed uploads when it is restarted
    • this will help you not to lose data.

If anyone would like to test this I'd be grateful for feedback. Note that it is new software so may have bugs and there are some rough edges...

This is currently in the vfs branch and the betas will look like this for it.

https://beta.rclone.org/branch/v1.52.0-038-g2571da3b-vfs-beta/ (uploaded in 15-30 mins)

I hope to merge this for 1.53 if I can get it bug free enough.

13 Likes

think about it!
full for the price of sparse
let's call it
the rclone diet :upside_down_face:

rclone source dest: --vfs-cache-mode=diet

1 Like

Hi, i Answer here :slight_smile:

Blockquote
Hmm, what kind of disk do you have? Is it very busy? --vfs-cache-mode full uses your disk much more.
Blockquote

That should not the Problem, there is a fast emmc module installed that can reach over 100 mb/s.

:Here is another Log with another Problem that happens on Music Playback on both Systems (Kodi on Linux and Winamp on Windows)

Logfile is from Windows 10.
At Track Change new Track Stutters/Hangs on the first seconds of Playback and winamp is not responding if this happens, sometines the first 2.3 seconds just playing fine.

Edit: I should say playing this files a second time, then the Playback is ok, i think it Plays ok because its Always in the Cache.

I think is happens Always if a new download is startet.

Blockquote
2020/06/05 07:14:17 DEBUG : XXX.flac: >newDownloader:
Blockquote

here is a Logfile: https://pastebin.com/23uYmqnb

test day 2:

  • Scenario: Nextcloud with symlink to mount drive. Works great with --vfs-cache-mode writes under v1.52.0 stable release. When I download a file with new --vfs-cache-mode full and abort it the server doesn't abort downloading the file from mount.
  • today I have poor performance with new --vfs-cache-mode full.
    image
    After 2 hours I got Error 403: downloadQuotaExceeded

I will create a debug log tomorrow.

Ah, I see what is happening.

In your log files I can see that the first 128k of the file got cached at some point - probably by the audio player reading metadata.

So when you came to play the file it played the first 128k just fine then it had to re-open the file on cloud storage and start streaming - that is what caused the stutter at the start.

I'm not sure what the bitrate of a .flac file but 128k is probably about right for 1-2 seconds.

Can you confirm this by finding a file you haven't played (but the audio player software has seen) and pasting the corresponding file out of the vfsMeta directory in the cache (rclone help flags cache-dir will show you where the directory is in the help)? It is a small JSON file which will show which chunks of the file have been downloaded.

I guess what rclone should be doing is this to avoid stutters

  • I'm reading data out of cache - all is good
  • Let's make sure I have data for at least x MB in advance of here
  • Oh no, I don't I only have 128k, so I'd better start reading

How are you aborting the file? Does the application you are using keep the file open?

Hi,

i don't know if that is the Right ouputtfile

Blockquote
{
"ModTime": "2020-06-05T11:01:26.889371+02:00",
"ATime": "2020-06-05T11:01:30.5188542+02:00",
"Size": 10865998,
"Rs": [
{
"Pos": 0,
"Size": 585728
},
{
"Pos": 10865838,
"Size": 160
}
],
"Fingerprint": "10865998,2020-01-25 17:24:05.855 +0000 UTC,bc83c0e2f19aa02448f307a179418bf9",
"Dirty": false
}

That was a file located in "vfsMeta\Google-G-Suite\UnverschlĂĽsselt\VFS-Test\DJ Cool Goes Schlager 4" that has the same Name as the flac file

Here are second file:

Blockquote
{
"ModTime": "2020-06-05T11:06:53.0763864+02:00",
"ATime": "2020-06-05T11:06:57.4134172+02:00",
"Size": 16167245,
"Rs": [
{
"Pos": 0,
"Size": 331776
}
],
"Fingerprint": "16167245,2020-01-25 17:24:06.59 +0000 UTC,763dd0525646897cb6db1a76f76f365f",
"Dirty": false
}

Flac Files have a Bitrate between 700kbps an 1200kbps (depends on the content of the Music)

Edit: if i replace the file from vfsMeta to AppData\Local\rclone\vfs\Google-G-Suite\UnverschlĂĽsselt\VFS-Test\DJ Cool Goes Schlager 4 (there is already a file with that filename an correct size) then i cannot Play that file.

That agrees with that I was thinking. Both those files show (in the Rs structure) a chunk at the start (Pos 0) of size 300k or 500k).

700kbps to 1200kbps for flac is about 90-150 kBytes/s so those buffered sizes represent 2-3 seconds most likely.

OK I'll work on a fix :slight_smile:

1 Like

Would that fix also help with the slowness I'm seeing downloading small jpegs for viewing? I'm using a webdav (vfs mode full now) serve through caddy. When I click to view jpegs, they are noticably slow to render. They appear to render in chunks in chrome and has to wait while the next chunk downloads which makes sense given how the vfs is supposed to only download the chunks we need.

2020/06/05 10:41:03 DEBUG : /REDACTED.jpg: OpenFile: flags=O_RDONLY, perm=----------
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: Open: flags=O_RDONLY
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: newRWFileHandle: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >newRWFileHandle: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >Open: fd=REDACTED.jpg (rw), err=<nil>
2020/06/05 10:41:03 DEBUG : /REDACTED.jpg: >OpenFile: fd=REDACTED.jpg (rw), err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): openPending: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: Open: item=0xc0065080c0
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: vfs cache: checking remote fingerprint "507653,2020-05-07 22:31:30.614 +0000 UTC" against cached fingerprint ""
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: vfs cache: truncate to size=507653
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >Open: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): >openPending: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=0
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: _ensure: offset=0, size=32768
2020/06/05 10:41:03 DEBUG : looking for range={Pos:0 Size:32768} in [] - present false
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: open: offset=0
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: ensure: r={Pos:0 Size:32768}
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: write chunk offset=0 size=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: write chunk offset=32768 size=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: _ensure: offset=32768, size=32768
2020/06/05 10:41:03 DEBUG : looking for range={Pos:32768 Size:32768} in [{Pos:0 Size:65536}] - present true
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=65536
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: _ensure: offset=65536, size=32768
2020/06/05 10:41:03 DEBUG : looking for range={Pos:65536 Size:32768} in [{Pos:0 Size:65536}] - present false
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: write chunk offset=65536 size=32768
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:03 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:03 DEBUG : REDACTED.jpg: open: offset=65536
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: ensure: r={Pos:65536 Size:32768}
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: skip chunk offset=65536 size=32768
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: write chunk offset=98304 size=32768
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=98304
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: _ensure: offset=98304, size=32768
2020/06/05 10:41:05 DEBUG : looking for range={Pos:98304 Size:32768} in [{Pos:0 Size:131072}] - present true
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=131072
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: _ensure: offset=131072, size=32768
2020/06/05 10:41:05 DEBUG : looking for range={Pos:131072 Size:32768} in [{Pos:0 Size:131072}] - present false
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: write chunk offset=131072 size=32768
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:05 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:05 DEBUG : REDACTED.jpg: open: offset=131072
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: ensure: r={Pos:131072 Size:32768}
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: skip chunk offset=131072 size=32768
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: write chunk offset=163840 size=32768
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=163840
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: _ensure: offset=163840, size=32768
2020/06/05 10:41:06 DEBUG : looking for range={Pos:163840 Size:32768} in [{Pos:0 Size:196608}] - present true
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=196608
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: _ensure: offset=196608, size=32768
2020/06/05 10:41:06 DEBUG : looking for range={Pos:196608 Size:32768} in [{Pos:0 Size:196608}] - present false
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: write chunk offset=196608 size=32768
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:06 DEBUG : REDACTED.jpg: open: offset=196608
2020/06/05 10:41:06 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: ensure: r={Pos:196608 Size:32768}
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: skip chunk offset=196608 size=32768
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: write chunk offset=229376 size=32768
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=229376
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: _ensure: offset=229376, size=32768
2020/06/05 10:41:07 DEBUG : looking for range={Pos:229376 Size:32768} in [{Pos:0 Size:262144}] - present true
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=262144
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: _ensure: offset=262144, size=32768
2020/06/05 10:41:07 DEBUG : looking for range={Pos:262144 Size:32768} in [{Pos:0 Size:262144}] - present false
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: write chunk offset=262144 size=32768
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:07 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:07 DEBUG : REDACTED.jpg: open: offset=262144
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: ensure: r={Pos:262144 Size:32768}
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: skip chunk offset=262144 size=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: write chunk offset=294912 size=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=294912
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: _ensure: offset=294912, size=32768
2020/06/05 10:41:08 DEBUG : looking for range={Pos:294912 Size:32768} in [{Pos:0 Size:327680}] - present true
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=327680
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: _ensure: offset=327680, size=32768
2020/06/05 10:41:08 DEBUG : looking for range={Pos:327680 Size:32768} in [{Pos:0 Size:327680}] - present false
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: write chunk offset=327680 size=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: open: offset=327680
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:08 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: ensure: r={Pos:327680 Size:32768}
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: skip chunk offset=327680 size=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: write chunk offset=360448 size=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=360448
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: _ensure: offset=360448, size=32768
2020/06/05 10:41:08 DEBUG : looking for range={Pos:360448 Size:32768} in [{Pos:0 Size:393216}] - present true
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=393216
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: _ensure: offset=393216, size=32768
2020/06/05 10:41:08 DEBUG : looking for range={Pos:393216 Size:32768} in [{Pos:0 Size:393216}] - present false
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: write chunk offset=393216 size=32768
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:08 DEBUG : REDACTED.jpg: open: offset=393216
2020/06/05 10:41:08 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: ensure: r={Pos:393216 Size:32768}
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: skip chunk offset=393216 size=32768
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: write chunk offset=425984 size=32768
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=425984
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: _ensure: offset=425984, size=32768
2020/06/05 10:41:09 DEBUG : looking for range={Pos:425984 Size:32768} in [{Pos:0 Size:458752}] - present true
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=32768, off=458752
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: _ensure: offset=458752, size=32768
2020/06/05 10:41:09 DEBUG : looking for range={Pos:458752 Size:32768} in [{Pos:0 Size:458752}] - present false
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: write chunk offset=458752 size=32768
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >download: err=vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc000044098 item:0xc0065080c0 src:0xc00207de80 fcache:0xc001e620a0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: open: offset=458752
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:09 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:09 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: ensure: r={Pos:458752 Size:32768}
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: download: 
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: skip chunk offset=458752 size=32768
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: Write: p_len=16133
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: write chunk offset=491520 size=16133
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >Write: n=16133, err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >download: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=32768, err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:10 DEBUG : REDACTED.jpg(0xc001c1e040): _readAt: size=16133, off=491520
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: _ensure: offset=491520, size=16133
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:10 DEBUG : looking for range={Pos:491520 Size:16133} in [{Pos:0 Size:507653}] - present true
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg(0xc001c1e040): >_readAt: n=16133, err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg(0xc001c1e040): close: 
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: Close: Item.Close
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: vfs cache: setting modification time to 2020-05-07 22:31:30.614 +0000 UTC
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: stop: 
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg: >Close: err=<nil>
2020/06/05 10:41:10 DEBUG : REDACTED.jpg(0xc001c1e040): >close: err=<nil>
2020/06/05 10:41:10 INFO  : /REDACTED.jpg: GET from 127.0.0.1:35002

cache-mode-writes behaves correctly. This may not be the best use case for 'full' but I was just testing impacts.

So in your case, "full" is worse than just "writes" ? It weird. I get that in some situations you won't have a huge benefit, but it shouldn't be worst than no read cache at all... ?

In this case it would be slower unless there is something wrong that ncw can fix. It seems that its doing what its supposed to in that it is downloading only the chunks it needs but i'd guess it would need a file size lower limit of where that would make sense. In this case grabbing such small chunks causes multiple calls where as it could have just downloaded the entire ~200k file.

OK here is a new version which implements --vfs-read-ahead. This defaults to 4MiB and is the amount rclone will try to get ahead in a stream.

This is a tradeoff between downloading stuff we don't need vs keeping the stuttering away!

Here it is!

https://beta.rclone.org/branch/v1.52.0-047-g708ccd13-vfs-beta/ (uploaded in 15-30 mins)

In your log I can see the file was re-opened 7 times which is odd since it looks like the browser read it sequentially by the looks of the offsets

2020/06/05 10:41:03 ERROR : REDACTED.jpg: Failed to download: vfs reader: failed to write to cache file: file already closed

There were an equivalent number of these errors which look like some kind of bug to me!

I'll study the log a bit more and see if I can work out what is going on!

I tested it without the reverse proxy in front (caddy) and it was the same. Just wanted to make sure caddy wasn't doing something weird.

@ncw , what is the default behaviour when the cache is full ? First in first out, or the least accessed chuncks are clean first ?

Thx !

Forgot to upload? :slight_smile: Still not online :frowning:

Sorry the push failed... build in progress now!

https://beta.rclone.org/branch/v1.52.0-047-g708ccd13-vfs-beta/ (uploaded in 15-30 mins)

1 Like

That build seemed to have fixed my issue. This is the new log.

2020/06/05 16:09:34 DEBUG : /REDACTED.jpg: OpenFile: flags=O_RDONLY, perm=----------
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: Open: flags=O_RDONLY
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: newRWFileHandle: 
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: >newRWFileHandle: err=<nil>
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: >Open: fd=REDACTED.jpg (rw), err=<nil>
2020/06/05 16:09:34 DEBUG : /REDACTED.jpg: >OpenFile: fd=REDACTED.jpg (rw), err=<nil>
2020/06/05 16:09:34 DEBUG : REDACTED.jpg(0xc004578080): openPending: 
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: Open: item=0xc0053d8000
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: vfs cache: checking remote fingerprint "205973,2020-05-07 22:35:25.546 +0000 UTC" against cached fingerprint ""
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: vfs cache: truncate to size=205973
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: >Open: err=<nil>
2020/06/05 16:09:34 DEBUG : REDACTED.jpg(0xc004578080): >openPending: err=<nil>
2020/06/05 16:09:34 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=32768, off=0
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: _ensure: offset=0, size=4194304
2020/06/05 16:09:34 DEBUG : looking for range={Pos:0 Size:205973} in [] - present false
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: newDownloader: remote="REDACTED.jpg"
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: >newDownloader: dl=&{mu:{state:0 sema:0} ctx:0xc0000440a8 item:0xc0053d8000 src:0xc00094a320 fcache:0xc001cd7ae0 osPath:/root/.cache/rclone/vfs/robgs-cryptp/Media/REDACTED.jpg out:<nil> offset:0 waiters:[] tr:<nil> in:<nil> downloading:false finished:<nil>}, err=<nil>
2020/06/05 16:09:34 DEBUG : REDACTED.jpg: open: offset=0
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >open: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: ensure: r={Pos:0 Size:205973}
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: download: 
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=0 size=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=32768 size=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=65536 size=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=98304 size=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=131072 size=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=163840 size=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Write: p_len=9365
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: write chunk offset=196608 size=9365
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Write: n=9365, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >download: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: stop: 
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=32768, off=32768
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: _ensure: offset=32768, size=4194304
2020/06/05 16:09:35 DEBUG : looking for range={Pos:32768 Size:173205} in [{Pos:0 Size:205973}] - present true
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=32768, off=65536
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: _ensure: offset=65536, size=4194304
2020/06/05 16:09:35 DEBUG : looking for range={Pos:65536 Size:140437} in [{Pos:0 Size:205973}] - present true
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=32768, off=98304
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: _ensure: offset=98304, size=4194304
2020/06/05 16:09:35 DEBUG : looking for range={Pos:98304 Size:107669} in [{Pos:0 Size:205973}] - present true
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=32768, off=131072
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: _ensure: offset=131072, size=4194304
2020/06/05 16:09:35 DEBUG : looking for range={Pos:131072 Size:74901} in [{Pos:0 Size:205973}] - present true
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=32768, off=163840
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: _ensure: offset=163840, size=4194304
2020/06/05 16:09:35 DEBUG : looking for range={Pos:163840 Size:42133} in [{Pos:0 Size:205973}] - present true
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=32768, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): _readAt: size=9365, off=196608
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: _ensure: offset=196608, size=4194304
2020/06/05 16:09:35 DEBUG : looking for range={Pos:196608 Size:9365} in [{Pos:0 Size:205973}] - present true
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >_ensure: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >_readAt: n=9365, err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): close: 
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: Close: Item.Close
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: vfs cache: setting modification time to 2020-05-07 22:35:25.546 +0000 UTC
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: close: inErr=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: stop: 
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >stop: 
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >close: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg: >Close: err=<nil>
2020/06/05 16:09:35 DEBUG : REDACTED.jpg(0xc004578080): >close: err=<nil>
2020/06/05 16:09:35 INFO  : /REDACTED.jpg: GET from 127.0.0.1:59712

My issues with Music & Video Playback are also fixed (on Windows), will try it with Kodi later.

Thank you ncw.

Speeds are definitely slower though using vfs full. Using curl I can max out my 200 gigbit link at home to my server. With the new vfs beta I get around 10-20 megabits. Even on the local server itself I get the same.

 curl  https://XXXX@XXXX:####/XXXX > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
 86  700M   86  607M    0     0  5050k      0  0:02:21  0:02:03  0:00:18 2827k

THis is in the normal 1.52 without just mode=writes:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  700M  100  700M    0     0  63.3M      0  0:00:11  0:00:11 --:--:-- 68.4M

It will evict the least accessed file (not chunk) first

1 Like