Testing for new vfs cache mode features

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

Good!

It may be worth experimenting with --vfs-read-ahead

Also good!

Try increasing VFS read ahead, that may help.

I haven't experimented with performance yet. Also try without debugging, the debugs are excessive right now!

Sorry but how do we disable the debugging ?

And, the vfs read ahead parameters is working on windows ? I believed it was only doing something on linux.

EDIT : oh it's working all right. And no speed problem here, I've a 8gb fiber link here, and rclone pull data around 2-4gb/s. But it seems it's pulling a lot more than necessary. Like in a few minutes my vfs cache is already at 44go (size on disk), and no way my torrent program has uploaded that much.... or accessed that much data. Maybe my vfs read ahead is too high ... Here my rclone mount command :

rclone.exe mount --cache-dir c:\mountcache --attr-timeout 8700h -vv --stats 10s --buffer-size 16M --vfs-cache-poll-interval 30s --poll-interval 60s --dir-cache-time 2h --async-read=true --vfs-read-wait 5ms --vfs-write-wait 10s --vfs-cache-mode full --vfs-read-ahead 16M --vfs-read-chunk-size 16M --vfs-read-chunk-size-limit 1G --use-mmap --local-no-check-updated --drive-chunk-size=256M --multi-thread-streams=4 --multi-thread-cutoff 250M --transfers 8 --drive-disable-http2=true --fast-list --vfs-case-insensitive --vfs-cache-max-size 200G "gdriveencryptedownapi:seedold" G:

tested this morning with debug log. I Think when I download the file opens / close serval times. When I abort this download (browser download via nextcloud) the server keeps reading the file. Netdata shows me alot of IOWAIT.

Ok so here it's caching the whole files, even if a few blocks are required by the torrent client. I put vfs read ahead at 0M, same thing. Right now for 600mb read, I've 34gb written to the disk as caching...