[Solved] Slow Read Speeds for Completely Cached Entries (Chunks Are Already Fully Downloaded)

What is the problem you are having with rclone?

Read speeds are slow for files that have already been cached in an rclone mount using the cache backend.

What is your rclone version (output from rclone version)

rclone v1.51.0-361-g9db8ecbc-beta

  • os/arch: linux/amd64
  • go version: go1.14.3

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

Ubuntu 20.04 LTS, 64 bit

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

Google Drive

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

[Unit]
Description=RClone Service
Wants=network-online.target
After=network-online.target

[Service]
Type=notify
Environment=RCLONE_CONFIG=/rclone/rclone.conf
KillMode=none
RestartSec=5
ExecStart=rclone mount cache: /mnt/cache \
--allow-other \
--log-level DEBUG \
--log-file /rclone/cache.log \
--poll-interval 15s \
--timeout 1h \
--umask 002

ExecStop=/bin/fusermount -uz /mnt/cache
Restart=on-failure
User=myusername

[Install]
WantedBy=multi-user.target

I am measuring read speeds by using the following command:

time dd if='archlinux-2019.10.01-x86_64.iso' of=/dev/null bs=8k

The rclone config contents with secrets removed.

[cache]
type = cache
remote = gdrive:
chunk_size = 1G
info_age = 1d
chunk_total_size = 3T
db_path = /rclone/cache-backend
chunk_path = /mnt/harddrive/cachechunks
workers = 4
chunk_no_memory = true

A log from the command with the -vv flag

I am providing a small excerpt since the log looks the same throughout.

2020/05/24 13:07:12 DEBUG : /: Lookup: name="archlinux-2019.10.01-x86_64.iso"
2020/05/24 13:07:12 DEBUG : /: >Lookup: node=archlinux-2019.10.01-x86_64.iso, err=<nil>
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: Attr: 
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: >Attr: a=valid=1s ino=0 size=657457152 mode=-rw-rw-r--, err=<nil>
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: Open: flags=OpenReadOnly
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: Open: flags=O_RDONLY
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: >Open: fd=archlinux-2019.10.01-x86_64.iso (r), err=<nil>
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: >Open: fh=&{archlinux-2019.10.01-x86_64.iso (r)}, err=<nil>
2020/05/24 13:07:12 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: Flush: 
2020/05/24 13:07:12 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: >Flush: err=<nil>
2020/05/24 13:07:12 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: Read: len=16384, offset=0
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.openRange at 0 length 134217728
2020/05/24 13:07:12 DEBUG : : Statfs: 
2020/05/24 13:07:12 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: moving offset set from 0 to 0
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: moving offset set from 0 to 0
2020/05/24 13:07:12 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 0 length 4096 chunkOffset 0 chunkSize 134217728
2020/05/24 13:07:13 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 4096 length 8192 chunkOffset 0 chunkSize 134217728
2020/05/24 13:07:13 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 12288 length 16384 chunkOffset 0 chunkSize 134217728
2020/05/24 13:07:13 DEBUG : /: Attr: 
2020/05/24 13:07:13 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2020/05/24 13:07:13 DEBUG : : Statfs: 
2020/05/24 13:07:13 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/05/24 13:07:13 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 28672 length 32768 chunkOffset 0 chunkSize 134217728
2020/05/24 13:07:13 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: >Read: read=16384, err=<nil>
2020/05/24 13:07:14 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: Read: len=65536, offset=49152
2020/05/24 13:07:14 DEBUG : archlinux-2019.10.01-x86_64.iso: waiting for in-sequence read to 49152 for 20ms
2020/05/24 13:07:14 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: Read: len=32768, offset=16384
2020/05/24 13:07:14 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 61440 length 65536 chunkOffset 0 chunkSize 134217728
2020/05/24 13:07:14 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: >Read: read=32768, err=<nil>
2020/05/24 13:07:14 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 126976 length 131072 chunkOffset 0 chunkSize 134217728
2020/05/24 13:07:14 DEBUG : archlinux-2019.10.01-x86_64.iso: aborting in-sequence read wait, off=49152
2020/05/24 13:07:14 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: >Read: read=65536, err=<nil>
2020/05/24 13:07:14 DEBUG : &{archlinux-2019.10.01-x86_64.iso (r)}: Read: len=131072, offset=114688
2020/05/24 13:07:14 DEBUG : : Statfs: 
2020/05/24 13:07:14 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2020/05/24 13:07:14 DEBUG : archlinux-2019.10.01-x86_64.iso: ChunkedReader.Read at 258048 length 262144 chunkOffset 0 chunkSize 134217728

Using the cache mount, I get

time dd if='archlinux-2019.10.01-x86_64.iso' of=/dev/null bs=8k
80256+0 records in
80256+0 records out
657457152 bytes (657 MB, 627 MiB) copied, 223.634 s, 2.9 MB/s

real	3m43.638s
user	0m0.141s
sys	0m0.791s

, where archlinux-2019.10.01-x86_64.iso has already been fully cached, that is, no download is taking place.

Directly reading from the hard drive location where the cache chunks are stored after running

echo 3 | sudo tee /proc/sys/vm/drop_caches

, I get

time dd if=0 of=/dev/null bs=8k
80256+0 records in
80256+0 records out
657457152 bytes (657 MB, 627 MiB) copied, 3.61745 s, 182 MB/s

real	0m3.629s
user	0m0.125s
sys	0m0.981s

, where 0 is the name of the relevant chunk. Note that 0 and archlinux-2019.10.01-x86_64.iso are the same file (verified by SHA1 sum).

The cache backend currently doesn't have a maintainer

The cache backend is due to be phased out in favor of the VFS caching layer eventually which is more tightly integrated into rclone.

The VFS backend will likely eventually fix this.

I changed my setup to use the VFS caching layer (--vfs-cache-mode full) and have found that it resolves the read speed issue.

1 Like

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