Rclone not downloading entire file before streaming

asdffdsa · March 27, 2021, 3:08pm

What is the problem you are having with rclone?

if
--vfs-read-chunk-size=128M
and
--vfs-read-ahead=1G
and
the file size = 99MB
then i would expect that rclone would read the first chunk and have downloaded that entire file into the vfs cache.
instead rclone is downloading many small chunks.
so what mistake or assumption am i making?
thanks much,

What is your rclone version (output from `rclone version`)

rclone v1.54.1
- os/arch: linux/arm
- go version: go1.15.8

Which OS you are using and how many bits (eg Windows 7, 64 bit)

raspberry pi zero raspbian os 32 bit
Linux raspberrypi 5.10.25+ #1408 Mon Mar 22 12:45:00 GMT 2021 armv6l GNU/Linux

Which cloud storage system are you using? (eg Google Drive)

The command you were trying to run (eg `rclone copy /tmp remote:tmp`)

rclone serve dlna remote:files/test --buffer-size=0 --addr=192.168.62.115:7879 --vfs-read-ahead=1G --cache-dir=/home/pi/rclone/cache --vfs-cache-mode=full --read-only --no-checksum --no-modtime --dir-cache-time=10000h --name=pizero --log-level=DEBUG --log-file=log.txt --progress

The rclone config contents with secrets removed.

[remote]
type = sftp
host = xxx.xxx.xxx
user = 
pass = 
md5sum_command = none
sha1sum_command = none

A log from the command with the `-vv` flag

DEBUG : rclone: Version "v1.54.1" starting with parameters ["rclone" "serve" "dlna" "remote:files/test" "--buffer-size=0" "--addr=192.168.62.115:7879" "--vfs-read-ahead=1G" "--cache-dir=/home/pi/rclone/cache" "--vfs-cache-mode=full" "--read-only" "--no-checksum" "--no-modtime" "--dir-cache-time=10000h" "--name=pizero" "--log-level=DEBUG" "--log-file=log.txt" "--progress"]
DEBUG : Using config file from "/home/pi/.config/rclone/rclone.conf"
DEBUG : Creating backend with remote "remote:files/test"
DEBUG : sftp://xxx@xxx.xxx.xxx:22/files/test: New connection 192.168.62.115:54458->xxx.xxx.xxx.xxx:22 to "SSH-2.0-mod_sftp"
DEBUG : sftp://xxx@xxx.xxx.xxx:22/files/test: Using absolute root directory "/files/test"
INFO  : sftp://xxx@xxx.xxx.xxx:22/files/test: poll-interval is not supported by this remote
DEBUG : vfs cache: root is "/home/pi/rclone/cache/vfs/remote/files/test"
DEBUG : vfs cache: metadata root is "/home/pi/rclone/cache/vfs/remote/files/test"
DEBUG : Creating backend with remote "/home/pi/rclone/cache/vfs/remote/files/test"
NOTICE: sftp://xxx@xxx.xxx.xxx:22/files/test: Serving HTTP on 192.168.62.115:7879
INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
INFO  : DLNA server on 192.168.62.115:7879: Started SSDP on wlan0
INFO  : /static/rclone-120x120.png: 192.168.62.242:39346 GET 200  
INFO  : /static/rclone-120x120.png: 192.168.62.242:39348 GET 200  
INFO  : /ctl: 192.168.62.242:39352 POST 200 "urn:schemas-upnp-org:service:ContentDirectory:1#Browse" 
DEBUG : file.mkv: Open: flags=O_RDONLY
DEBUG : file.mkv: newRWFileHandle: 
DEBUG : file.mkv: >newRWFileHandle: err=<nil>
DEBUG : file.mkv: >Open: fd=file.mkv (rw), err=<nil>
DEBUG : file.mkv(0x331bf20): openPending: 
DEBUG : file.mkv: vfs cache: checking remote fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC" against cached fingerprint ""
DEBUG : file.mkv: vfs cache: truncate to size=98978912
DEBUG : : Added virtual directory entry vAddFile: "file.mkv"
DEBUG : file.mkv(0x331bf20): >openPending: err=<nil>
INFO  : /r/file.mkv: 192.168.62.242:39354 GET 206  
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=0
DEBUG : vfs cache: looking for range={Pos:0 Size:32768} in [] - present false
DEBUG : file.mkv: ChunkedReader.RangeSeek from -1 to 0 length -1
DEBUG : file.mkv: ChunkedReader.Read at -1 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.openRange at 0 length 134217728
DEBUG : file.mkv: ChunkedReader.Read at 32768 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=32768
DEBUG : vfs cache: looking for range={Pos:32768 Size:32768} in [{Pos:0 Size:32768}] - present false
DEBUG : file.mkv: Open: flags=O_RDONLY
DEBUG : file.mkv: newRWFileHandle: 
DEBUG : file.mkv: >newRWFileHandle: err=<nil>
DEBUG : file.mkv: >Open: fd=file.mkv (rw), err=<nil>
DEBUG : file.mkv(0x315c2d0): openPending: 
DEBUG : file.mkv: vfs cache: checking remote fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC" against cached fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC"
DEBUG : file.mkv: vfs cache: truncate to size=98978912
DEBUG : : Added virtual directory entry vAddFile: "file.mkv"
DEBUG : file.mkv(0x315c2d0): >openPending: err=<nil>
INFO  : /r/file.mkv: 192.168.62.242:39356 GET 206  
DEBUG : file.mkv(0x315c2d0): _readAt: size=21253, off=98957659
DEBUG : vfs cache: looking for range={Pos:98957659 Size:21253} in [{Pos:0 Size:32768}] - present false
DEBUG : file.mkv: ChunkedReader.RangeSeek from -1 to 98957659 length -1
DEBUG : file.mkv: ChunkedReader.Read at 65536 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=65536
DEBUG : vfs cache: looking for range={Pos:65536 Size:32768} in [{Pos:0 Size:65536}] - present false
DEBUG : file.mkv: ChunkedReader.Read at -1 length 32768 chunkOffset 98957659 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.openRange at 98957659 length 134217728
DEBUG : file.mkv: ChunkedReader.Read at 98304 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=98304
DEBUG : vfs cache: looking for range={Pos:98304 Size:32768} in [{Pos:0 Size:98304}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 131072 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=131072
DEBUG : vfs cache: looking for range={Pos:131072 Size:32768} in [{Pos:0 Size:131072}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 163840 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=163840
DEBUG : vfs cache: looking for range={Pos:163840 Size:32768} in [{Pos:0 Size:163840}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 196608 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=196608
DEBUG : vfs cache: looking for range={Pos:196608 Size:32768} in [{Pos:0 Size:196608}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 229376 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=229376
DEBUG : vfs cache: looking for range={Pos:229376 Size:32768} in [{Pos:0 Size:229376}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 262144 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=262144
DEBUG : vfs cache: looking for range={Pos:262144 Size:32768} in [{Pos:0 Size:262144}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 294912 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=294912
DEBUG : vfs cache: looking for range={Pos:294912 Size:32768} in [{Pos:0 Size:294912}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 327680 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=327680
DEBUG : vfs cache: looking for range={Pos:327680 Size:32768} in [{Pos:0 Size:327680}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 360448 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=360448
DEBUG : vfs cache: looking for range={Pos:360448 Size:32768} in [{Pos:0 Size:360448}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 393216 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=393216
DEBUG : vfs cache: looking for range={Pos:393216 Size:32768} in [{Pos:0 Size:393216}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 425984 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=425984
DEBUG : vfs cache: looking for range={Pos:425984 Size:32768} in [{Pos:0 Size:425984}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 458752 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=458752
DEBUG : vfs cache: looking for range={Pos:458752 Size:32768} in [{Pos:0 Size:458752}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 491520 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=491520
DEBUG : vfs cache: looking for range={Pos:491520 Size:32768} in [{Pos:0 Size:491520}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 524288 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=524288
DEBUG : vfs cache: looking for range={Pos:524288 Size:32768} in [{Pos:0 Size:524288}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 557056 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 589824 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=557056
DEBUG : vfs cache: looking for range={Pos:557056 Size:32768} in [{Pos:0 Size:589824}] - present true
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=589824
DEBUG : vfs cache: looking for range={Pos:589824 Size:32768} in [{Pos:0 Size:589824}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 622592 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 655360 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=622592
DEBUG : vfs cache: looking for range={Pos:622592 Size:32768} in [{Pos:0 Size:655360}] - present true
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=655360
DEBUG : vfs cache: looking for range={Pos:655360 Size:32768} in [{Pos:0 Size:655360}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 688128 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 720896 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=688128
DEBUG : vfs cache: looking for range={Pos:688128 Size:32768} in [{Pos:0 Size:720896}] - present true
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=720896
DEBUG : vfs cache: looking for range={Pos:720896 Size:32768} in [{Pos:0 Size:720896}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 753664 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=753664
DEBUG : vfs cache: looking for range={Pos:753664 Size:32768} in [{Pos:0 Size:753664}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 786432 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=786432
DEBUG : vfs cache: looking for range={Pos:786432 Size:32768} in [{Pos:0 Size:786432}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 819200 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=819200
DEBUG : vfs cache: looking for range={Pos:819200 Size:32768} in [{Pos:0 Size:819200}] - present false
DEBUG : file.mkv: ChunkedReader.Read at 851968 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=851968
DEBUG : vfs cache: looking for range={Pos:851968 Size:32768} in [{Pos:0 Size:851968}] - present false
DEBUG : file.mkv(0x315c2d0): >_readAt: n=21253, err=<nil>
DEBUG : file.mkv(0x315c2d0): close: 
DEBUG : file.mkv(0x315c2d0): >close: err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 884736 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): _readAt: size=32768, off=884736
DEBUG : vfs cache: looking for range={Pos:884736 Size:32768} in [{Pos:0 Size:884736} {Pos:98957659 Size:21253}] - present false
DEBUG : file.mkv: Open: flags=O_RDONLY
DEBUG : file.mkv: newRWFileHandle: 
DEBUG : file.mkv: >newRWFileHandle: err=<nil>
DEBUG : file.mkv: >Open: fd=file.mkv (rw), err=<nil>
DEBUG : file.mkv(0x315d200): openPending: 
DEBUG : file.mkv: vfs cache: checking remote fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC" against cached fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC"
DEBUG : file.mkv: vfs cache: truncate to size=98978912
DEBUG : : Added virtual directory entry vAddFile: "file.mkv"
DEBUG : file.mkv(0x315d200): >openPending: err=<nil>
INFO  : /r/file.mkv: 192.168.62.242:39382 GET 206  
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=91
DEBUG : vfs cache: looking for range={Pos:91 Size:32768} in [{Pos:0 Size:917504} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=32859
DEBUG : vfs cache: looking for range={Pos:32859 Size:32768} in [{Pos:0 Size:917504} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x331bf20): close: 
DEBUG : file.mkv(0x331bf20): >close: err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 917504 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 950272 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 983040 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1015808 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1048576 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1081344 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1114112 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=65627
DEBUG : file.mkv: ChunkedReader.Read at 1146880 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1179648 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1212416 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1245184 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1277952 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: Open: flags=O_RDONLY
DEBUG : vfs cache: looking for range={Pos:65627 Size:32768} in [{Pos:0 Size:1277952} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv: ChunkedReader.Read at 1310720 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 1343488 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: newRWFileHandle: 
DEBUG : file.mkv: >newRWFileHandle: err=<nil>
DEBUG : file.mkv: >Open: fd=file.mkv (rw), err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 1376256 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=98395
DEBUG : vfs cache: looking for range={Pos:98395 Size:32768} in [{Pos:0 Size:1376256} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315c240): openPending: 
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=131163
DEBUG : vfs cache: looking for range={Pos:131163 Size:32768} in [{Pos:0 Size:1409024} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=163931
DEBUG : vfs cache: looking for range={Pos:163931 Size:32768} in [{Pos:0 Size:1409024} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=196699
DEBUG : file.mkv: ChunkedReader.Read at 1409024 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: vfs cache: checking remote fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC" against cached fingerprint "98978912,2021-03-26 20:24:03 +0000 UTC"
DEBUG : file.mkv: vfs cache: truncate to size=98978912
DEBUG : : Added virtual directory entry vAddFile: "file.mkv"
DEBUG : file.mkv(0x315c240): >openPending: err=<nil>
INFO  : /r/file.mkv: 192.168.62.242:39384 GET 206  
DEBUG : file.mkv(0x315c240): _readAt: size=32768, off=98941610
DEBUG : vfs cache: looking for range={Pos:98941610 Size:32768} in [{Pos:0 Size:1409024} {Pos:98957659 Size:21253}] - present false
DEBUG : vfs cache: looking for range={Pos:196699 Size:32768} in [{Pos:0 Size:1409024} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv: ChunkedReader.RangeSeek from -1 to 98941610 length -1
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=229467
DEBUG : vfs cache: looking for range={Pos:229467 Size:32768} in [{Pos:0 Size:1441792} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv: ChunkedReader.Read at -1 length 32768 chunkOffset 98941610 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.openRange at 98941610 length 134217728
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=262235
DEBUG : vfs cache: looking for range={Pos:262235 Size:32768} in [{Pos:0 Size:1441792} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=295003
DEBUG : file.mkv: ChunkedReader.Read at 1441792 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : vfs cache: looking for range={Pos:295003 Size:32768} in [{Pos:0 Size:1441792} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=327771
DEBUG : vfs cache: looking for range={Pos:327771 Size:32768} in [{Pos:0 Size:1474560} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=360539
DEBUG : vfs cache: looking for range={Pos:360539 Size:32768} in [{Pos:0 Size:1474560} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=393307
DEBUG : vfs cache: looking for range={Pos:393307 Size:32768} in [{Pos:0 Size:1474560} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv: ChunkedReader.Read at 1474560 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 1507328 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1540096 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1572864 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1605632 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=426075
DEBUG : vfs cache: looking for range={Pos:426075 Size:32768} in [{Pos:0 Size:1605632} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=458843
DEBUG : vfs cache: looking for range={Pos:458843 Size:32768} in [{Pos:0 Size:1605632} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=491611
DEBUG : vfs cache: looking for range={Pos:491611 Size:32768} in [{Pos:0 Size:1605632} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=524379
DEBUG : vfs cache: looking for range={Pos:524379 Size:32768} in [{Pos:0 Size:1605632} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=557147
DEBUG : vfs cache: looking for range={Pos:557147 Size:32768} in [{Pos:0 Size:1605632} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=589915
DEBUG : vfs cache: looking for range={Pos:589915 Size:32768} in [{Pos:0 Size:1605632} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 1638400 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1671168 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1703936 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1736704 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1769472 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1802240 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv(0x315d200): _readAt: size=32768, off=622683
DEBUG : file.mkv: ChunkedReader.Read at 1835008 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1867776 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : vfs cache: looking for range={Pos:622683 Size:32768} in [{Pos:0 Size:1867776} {Pos:98957659 Size:21253}] - present true
DEBUG : file.mkv(0x315d200): >_readAt: n=32768, err=<nil>
DEBUG : file.mkv(0x315d200): close: 
DEBUG : file.mkv(0x315d200): >close: err=<nil>
DEBUG : file.mkv: ChunkedReader.Read at 1900544 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1933312 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1966080 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 1998848 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2031616 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2064384 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2097152 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2129920 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2162688 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2195456 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2228224 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2260992 length 32768 chunkOffset 0 chunkSize 134217728
DEBUG : file.mkv: ChunkedReader.Read at 2293760 length 32768 chunkOffset 0 chunkSize 134217728

Animosity022 · March 27, 2021, 3:14pm

You aren't sequentially reading the file.

It's doing range seeks in the file, which you can't read ahead if you are seeking.

You can see the opens/closes/Seeks in the log.

asdffdsa · March 27, 2021, 3:44pm

i thought that the seeking was the problem, as it was working with file copying.
thanks for confirming

system · May 27, 2021, 11:45am

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