rclone: rclone multi-thread copy is slow on local write

What is the problem you are having with rclone?

Rclone takes significantly more time to write a file than cp unix command.

I traced it down to multi-thread copy being slow, at least in that case.

I conducted an experiment where we have 1GB a file that is not cached and try to copy that to an empty directory. With cp we have runtime of about a second.

$ pcstat 1GB.bin.1
+-----------+----------------+------------+-----------+---------+
| Name      | Size (bytes)   | Pages      | Cached    | Percent |
|-----------+----------------+------------+-----------+---------|
| 1GB.bin.1 | 1073741824     | 262144     | 0         | 000.000 |
+-----------+----------------+------------+-----------+---------+
$ taskset -c 0 /usr/bin/time -v cp 1GB.bin.1 /var/empty/rclone/
        Command being timed: "cp 1GB.bin.1 /var/empty/rclone/"
        User time (seconds): 0.00
        System time (seconds): 0.50
        Percent of CPU this job got: 44%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.14
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 2492
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 1
        Minor (reclaiming a frame) page faults: 152
        Voluntary context switches: 3769
        Involuntary context switches: 28
        Swaps: 0
        File system inputs: 2097696
        File system outputs: 2097152
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

While with rclone it’s like 15s.

$ taskset -c 0 /usr/bin/time -v ./rclone copy 1GB.bin.1 /var/empty/rclone
        Command being timed: "./rclone copy 1GB.bin.1 /var/empty/rclone"
        User time (seconds): 14.46
        System time (seconds): 0.81
        Percent of CPU this job got: 93%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:16.41
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 27600
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 2228
        Voluntary context switches: 7190
        Involuntary context switches: 1980
        Swaps: 0
        File system inputs: 2097152
        File system outputs: 2097152
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

This is quite surprising as plain io.Copy code is almost as fast as cp

package main

import (
	"flag"
	"io"
	"os"
)

func main() {
	src := flag.String("src", "", "")
	dst := flag.String("dst", "", "")
	mode := flag.Int("mode", 0, "")
	flag.Parse()

	var err error
	switch *mode {
	case 0:
		err = stdCopy(*src, *dst)
	default:
		panic("No such mode")
	}
	if err != nil {
		panic(err)
	}
}

func stdCopy(src, dst string) error {
	r, err := os.OpenFile(src, os.O_RDONLY, 0)
	if err != nil {
		return err
	}
	w, err := os.OpenFile(dst, os.O_RDWR|os.O_CREATE|os.O_TRUNC, 0666)
	if err != nil {
		return err
	}

	if _, err := io.Copy(w, r); err != nil {
		return err
	}
	if err = r.Close(); err != nil {
		return err
	}
	if err = w.Close(); err != nil {
		return err
	}

	return nil
}

$ pcstat 1GB.bin
+---------+----------------+------------+-----------+---------+
| Name    | Size (bytes)   | Pages      | Cached    | Percent |
|---------+----------------+------------+-----------+---------|
| 1GB.bin | 1073741824     | 262144     | 0         | 000.000 |
+---------+----------------+------------+-----------+---------+
$ taskset -c 0 /usr/bin/time -v ./poc -mode 0 -src 1GB.bin -dst /var/empty/rclone/1GB.bin
        Command being timed: "./poc -mode 0 -src 1GB.bin -dst /var/empty/rclone/1GB.bin"
        User time (seconds): 0.06
        System time (seconds): 0.59
        Percent of CPU this job got: 44%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:01.50
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 1572
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 156
        Voluntary context switches: 33945
        Involuntary context switches: 11214
        Swaps: 0
        File system inputs: 2097152
        File system outputs: 2097152
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

What is your rclone version (output from rclone version)

commit d51a970932fc5b6af551b1e663bd184f2083efe6

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

Linux lh 5.2.5-200.fc30.x86_64 #1 SMP Wed Jul 31 14:37:17 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

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

Only local

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

rclone copy 1GB.bin.1 /var/empty/rclone

A log from the command with the -vv flag (eg output from rclone -vv copy /tmp remote:tmp)

 michal@lh:scylla/rclone (master)$ ./rclone -vv copy 1GB.bin.2 /var/empty/rclone
2019/08/08 12:03:26 DEBUG : rclone: Version "v1.48.0-114-gd51a9709-beta" starting with parameters ["./rclone" "-vv" "copy" "1GB.bin.2" "/var/empty/rclone"]
2019/08/08 12:03:26 DEBUG : Using config file from "/home/michal/.config/rclone/rclone.conf"
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: Couldn't find file - need to transfer
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: Starting multi-thread copy with 4 parts of size 256M
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 4/4 (805306368-1073741824) size 256M starting
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 2/4 (268435456-536870912) size 256M starting
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 1/4 (0-268435456) size 256M starting
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 3/4 (536870912-805306368) size 256M starting
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 4/4 (805306368-1073741824) size 256M finished
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 3/4 (536870912-805306368) size 256M finished
2019/08/08 12:03:26 DEBUG : 1GB.bin.2: multi-thread copy: stream 2/4 (268435456-536870912) size 256M finished
2019/08/08 12:03:36 DEBUG : 1GB.bin.2: multi-thread copy: stream 1/4 (0-268435456) size 256M finished
2019/08/08 12:03:36 DEBUG : 1GB.bin.2: Finished multi-thread copy with 4 parts of size 256M
2019/08/08 12:03:39 INFO  : 1GB.bin.2: Multi-thread Copied (new)
2019/08/08 12:03:39 INFO  : 
Transferred:            1G / 1 GBytes, 100%, 74.522 MBytes/s, ETA 0s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            1 / 1, 100%
Elapsed time:       13.7s

When running without the multi-thread copy - we have 10x improvement.

$ ./rclone -vv copy --multi-thread-cutoff 10G 1GB.bin.2 /var/empty/rclone
2019/08/08 12:06:11 DEBUG : rclone: Version "v1.48.0-114-gd51a9709-beta" starting with parameters ["./rclone" "-vv" "copy" "--multi-thread-cutoff" "10G" "1GB.bin.2" "/var/empty/rclone"]
2019/08/08 12:06:11 DEBUG : Using config file from "/home/michal/.config/rclone/rclone.conf"
2019/08/08 12:06:11 DEBUG : 1GB.bin.2: Couldn't find file - need to transfer
2019/08/08 12:06:13 INFO  : 1GB.bin.2: Copied (new)
2019/08/08 12:06:13 INFO  : 
Transferred:            1G / 1 GBytes, 100%, 551.474 MBytes/s, ETA 0s
Errors:                 0
Checks:                 0 / 0, -
Transferred:            1 / 1, 100%
Elapsed time:        1.8s

2019/08/08 12:06:13 DEBUG : 3 go routines active
2019/08/08 12:06:13 DEBUG : rclone: Version "v1.48.0-114-gd51a9709-beta" finishing with parameters ["./rclone" "-vv" "copy" "--multi-thread-cutoff" "10G" "1GB.bin.2" "/var/empty/rclone"]