Copy from local to s3 has high memory usage

What is the problem you are having with rclone?

When copying a large local file (600+gb) to amazon s3 the rclone process uses a lot of memory, 2gb+. This makes it impossible to have multiple transfers going without hitting the OOM killer (at 3gb).

What is your rclone version (output from rclone version)

rclone v1.50.2

  • os/arch: freebsd/386
  • go version: go1.13.4

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

FreeBSD 11.1-STABLE, 64-bit

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

Amazon S3

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

/root/Rclone/rclone-v1.50.2-freebsd-386/rclone copy /mnt/pool4 HAGSC_AWS:hudsonalpha-gsc/freenas5/mnt/pool4 --links --min-size 600G --max-size 800G --use-mmap --no-traverse --transfers 1 --buffer-size 0 --checkers 1 -vv --log-file=l1 --rc

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

https://hagsc.org/~flowers/s3_issues.txt

And here's pprof output:

./go/bin/go tool pprof -text http://localhost:5572/debug/pprof/heap
Fetching profile over HTTP from http://localhost:5572/debug/pprof/heap
Saved profile in /root/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
Type: inuse_space
Time: Dec 16, 2019 at 4:45pm (CST)
Showing nodes accounting for 960MB, 99.94% of 960.53MB total
Dropped 3 nodes (cum <= 4.80MB)
      flat  flat%   sum%        cum   cum%
     960MB 99.94% 99.94%      960MB 99.94%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*uploader).init.func1
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/backend/s3.(*Fs).Put
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/backend/s3.(*Object).Update
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/backend/s3.(*Object).Update.func2
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*multiuploader).upload
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*uploader).nextReader
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*uploader).upload
         0     0% 99.94%      960MB 99.94%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.Uploader.UploadWithContext
         0     0% 99.94%      960MB 99.94%  sync.(*Pool).Get

rclone.conf:

[HAGSC_AWS]
type = s3
provider = AWS
env_auth =
access_key_id = XXXXX
secret_access_key = XXXXX
region = us-east-1
acl = private
server_side_encryption =

I also set GOGC=20 before starting rclone this time, although it doesn't seem to be making much of a difference.

That is the s3 uploader's buffers... Which looks a bit on the large size.

The concurrency by default is

  --s3-upload-concurrency int         Concurrency for multipart uploads. (default 4)

I think the chunk sizes will be quite large though to fit inside the 10,000 limit. I see in your log a 3.368TB file. That would need a chunk size of 3.368TB/10000 = 336.8MB and with a concurrency of 4 you'll need 4 of those so 1347MB.

I think this starts to explain where the memory usage is coming from. I'm not sure why exactly the s3 uploader uses such a lot of memory though.

To use less memory set --s3-concurrency lower.

Or if you want to use the least memory then you can set --s3-upload-cutoff 100T which will upload the files in a single part and not use any in memory buffers. This will work provided they are < 5TB and will use very little extra memory. However any failures will mean the whole thing is retried rather than just the chunk.

Well, there's no one file of 3TB, it's that there're 5 files of 600-800gb, so it shouldn't be allocating an upload buffer for all the files when it's uploading one at a time. Right?

I also thought --s3-upload-cutoff had a max of 5gb? At least, that's what https://rclone.org/s3/ says. And that's what my version of rclone says, too - it bombed out when I tried 100T.

This code is in the AWS SDK... it is a bit convoluted but I think it should allocate chunks as it needs them then free them in the end.

The memory profile is conclusive that the memory is being allocated there though.

Does the memory usage rise over time?

In general it is quite hard to leak memory in go without leaking something else like goroutines, so it might be worth doing a goroutine trace too.

Sorry, brain fart, 5G is the limit!

Did you try setting --s3-concurrency 1 ?

Yeah, I can get it to fit under the memory limit with setting concurrency to 1, but it's rather slow (8mb/s).

It doesn't look like a memory leak - while the memory can rise over time, it's very slow, and it can also go down, so I think it's more likely just standard garbage collection activity.

Thanks for your help, but I think we'll probably just use a different client. AWS has a cli that isn't quite as nice as rclone, but it looks like it'll have much better transfer rates in this environment.

Just a note - with less restrictive options, this uses less memory under linux:

rclone v1.50.2

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

NAME="Ubuntu"
VERSION="16.04.5 LTS (Xenial Xerus)"

rclone copy /home/f5p4 HAGSC_AWS:hudsonalpha-gsc/freenas5/mnt/pool4 --links --min-size 300G --no-traverse -vv --log-file=l --rc --s3-upload-concurrency=16 --transfers=1

topped out (very briefly, likely just before garbage collection kicked in) at 2g, transferring files as large as 648 gb, and generally ran at 1gb or less. These were the same files as before, just from a remote machine over nfs instead of on the file server.

Actually, here's a memory trace:

Fetching profile over HTTP from http://localhost:5572/debug/pprof/heap
Saved profile in /home/flowers/pprof/pprof.rclone.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: rclone
Type: inuse_space
Time: Dec 23, 2019 at 5:31pm (UTC)
Showing nodes accounting for 854MB, 98.80% of 864.39MB total
Dropped 62 nodes (cum <= 4.32MB)
      flat  flat%   sum%        cum   cum%
     854MB 98.80% 98.80%      854MB 98.80%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*uploader).init.func1
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/backend/s3.(*Fs).Put
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/backend/s3.(*Object).Update
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/backend/s3.(*Object).Update.func2
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 98.80%   854.50MB 98.86%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 98.80%   854.50MB 98.86%  github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*multiuploader).upload
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*uploader).nextReader
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.(*uploader).upload
         0     0% 98.80%      854MB 98.80%  github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/service/s3/s3manager.Uploader.UploadWithContext
         0     0% 98.80%   854.50MB 98.86%  sync.(*Pool).Get

So the apparent big memory object seems to be using the same amount of memory in both cases, roughly, despite having s3--upload-concurrency of 16 vs the default of 4. Which means the extra 2gb the freebsd case was using both isn't tracked by the go memory trace and isn't present in the linux version, whatever it is.

Hmm!

Those allocations are in the s3 uploader which is in the AWS SDK.

This is the line of code which does the allocations

Which calls this

Making a sync.Pool to store chunks.

sync.Pool has a reputation for hanging on to memory longer than it needs to.

I'm not really sure what is going on here - fancy doing a bit more investigation?

I've just been trawling through bug reports in the AWS s3 sdk...

This one looks extremely relevant

I've pulled that fix into the latest beta - can you have a go with that?

I pulled the latest s3 sdk in upgrading it from to v1.26.8 from v1.25.31

Can you have a go with this?

https://beta.rclone.org/branch/v1.50.2-095-ge332d3e0-fix-s3-memory-beta/ (uploaded in 15-30 mins)

One other thing you could try is

export GOGC=20

this tells the go garbage collector to work harder at the cost of more CPU.

After multiple complaints about s3 using too much memory for multipart uploads I've re-written the uploader. I was using the one from the AWS SDK but there are loads of reports of it using lots of memory.

Can you have a go with this which should hopefully fix the problem.

https://beta.rclone.org/branch/v1.50.2-095-g5363afa7-fix-s3-manager-beta/

Seems to be working. I'll have more details later. Unfortunately, I don't have any more 600gb+ files to test with (I transferred them all already using the linux machine), but I'm trying with 4 200gb+ files at once, and it's under 1gb of total memory usage for now.

That is great - thank you for testing.

What other flags are you using in your rclone command?

/root/Rclone/rclone-v1.50.2-095-g5363afa7-fix-s3-manager-beta-freebsd-386/rclone copy /mnt/pool4 HAGSC_AWS:hudsonalpha-gsc/freenas5/mnt/pool4 --links --no-traverse -vv --log-file=l --rc --min-size=200G

I did not set GOGC=20 for this run.

Memory usage has grown over time, but is still quite reasonable. Here's a trace over time of RES for the process as reported by top (size followed by minutes at that size):

542M 1
590M 1
629M 1
631M 1
641M 1
642M 1
643M 6
649M 24
651M 17
652M 8
655M 47
657M 1
757M 4
872M 13
923M 2
924M 104
950M 1
975M 87
1035M 20
1108M 191
1133M 98
1193M 107

It's a little concerning that's it's only increasing over time, though, as the sizes of the files being uploaded have been fairly consistent over the run (roughly 225gb each, uploading four at a time). On the other hand, it does seem to have mostly settled down, and it's probably just garbage collection accumulation (at around 2x the starting size).

Here's the go memory profile (I ran it earlier in the run as well, and results were about the same):

root@freenas5:~ # ./go/bin/go tool pprof -text http://localhost:5572/debug/pprof/heap
Fetching profile over HTTP from http://localhost:5572/debug/pprof/heap
Saved profile in /root/pprof/pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Type: inuse_space
Time: Jan 3, 2020 at 11:40am (CST)
Showing nodes accounting for 421.70MB, 98.70% of 427.23MB total
Dropped 62 nodes (cum <= 2.14MB)
      flat  flat%   sum%        cum   cum%
  368.50MB 86.25% 86.25%      369MB 86.37%  github.com/rclone/rclone/backend/s3.(*Object).uploadMultipart
   53.20MB 12.45% 98.70%    53.20MB 12.45%  github.com/rclone/rclone/lib/pool.New.func1
         0     0% 98.70%      369MB 86.37%  github.com/rclone/rclone/backend/s3.(*Fs).Put
         0     0% 98.70%      369MB 86.37%  github.com/rclone/rclone/backend/s3.(*Object).Update
         0     0% 98.70%    53.20MB 12.45%  github.com/rclone/rclone/fs/asyncreader.(*AsyncReader).getBuffer
         0     0% 98.70%    53.20MB 12.45%  github.com/rclone/rclone/fs/asyncreader.(*AsyncReader).init.func1
         0     0% 98.70%   369.50MB 86.49%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 98.70%   369.50MB 86.49%  github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove
         0     0% 98.70%    53.20MB 12.45%  github.com/rclone/rclone/lib/pool.(*Pool).Get

That is exactly how much memory I'd expect to see in use for 225 GB files.

The go runtime seems not to be returning unused memory to the OS which is odd...

It looks like this may be a known issue in the go runtime: https://github.com/golang/go/issues/32519