Rclone rc High memory usage

mama · February 3, 2020, 11:41am

Hi
I am using rclone rc version 1.49 to list files within 3 days max-age in a linux machine and copying them into ObjectStore.
The application sends rclone list command to a remote machine every 5min, after processing retrieved list of files it send rclone rc sync/copy command to copy only the directories that we know do not exists in ObjectStore. The frequency of copy command is only couple of times per hours and each directory is about 20M.
On every occasion the rclone-rc process was using a huge amount of system resources, particularly system memory and caches, well over 60% of system ram (nearly 10 Gb!), another 15 Gb of swap space.

any help to debug such memory leakage will be highly appreciated

Animosity022 · February 3, 2020, 1:04pm

That's an old version. You'd want to upgrade and check this link for helping debug a memory related issue:

https://rclone.org/rc/#debugging-rclone-with-pprof

mama · February 3, 2020, 2:12pm

Thanks for the reply. As we are in prod env changing version is not that easy
Do you think upgrading rclone will resolve the issue? Actually rclone on Windows has no memory issue. We only have problem with linux one.
Also I read about mmap flag. Is the fix in the latest version has something to do with mmap flag. Do we need to enable it to see the difference.

Animosity022 · February 3, 2020, 2:15pm

There have been a number of leaks fixed over the last releases so it's definitely likely!

mama · February 3, 2020, 2:58pm

While we are testing new version of rclone I have another question.
We have set JobExpireDuration to 1 day. Do you think this may contribute to such high memory usage?

mama · February 3, 2020, 4:35pm

I am getting error while trying go pprof as described in the above link.
https://ip:port/debug/pprof/goroutine?debug=1: Get https://ip:port/debug/pprof/goroutine?debug=1: x509: cannot validate certificate for <ip> because it doesn't contain any IP SANs

How can I make it not to check the certificate?

Thanks

Animosity022 · February 3, 2020, 4:46pm

That’s something on your side as it’s just a public website link.

Are you using a proxy or something else in the middle?

darthShadow · February 3, 2020, 5:36pm

The browser is probably trying to redirect the HTTP traffic to HTTPS which won't work since rclone doesn't include any SSL certificate for the rc. You need to change it to to the http variant, not the https variant.

ncw · February 4, 2020, 11:17am

How many jobs? I'd guess a job might take 1k of RAM to store.

mama · February 4, 2020, 1:29pm

Hi Nick
As soon as running the rclone it starts to create a job per second even if we do not send any rc command. I used job/status to see what are these jobs and they look like core/stats output

rclone rc job/status --json '{"jobid":27438}'  --rc-addr=http://user:pas@ip:1235
{
	"duration": 0.000009134,
	"endTime": "2020-02-04T13:04:51.7177Z",
	"error": "",
	"finished": true,
	"group": "job/27438",
	"id": 27438,
	"output": {
		"bytes": 0,
		"checks": 0,
		"deletes": 0,
		"elapsedTime": 0,
		"errors": 0,
		"fatalError": false,
		"retryError": false,
		"speed": 0,
		"transfers": 0
	},
	"startTime": "2020-02-04T13:04:51.717691Z",
	"success": true
}

rclone generates jobs like this every sec!!
Yesterday after an hour of running rclone I had about 1500 jobs and this number kept growing.
Now, I reduced JobExpireDuration to 2h and currently having only 170 jobs.

But still we have memory problem only on linux machines memory usage just keeps growing linearly until rclone uses about 60% of memory (nearly 10 Gb!, and another 15 Gb of swap space) and the server crash.
We upgraded rclone to v1.51 but no difference

Animosity022 · February 4, 2020, 1:37pm

Can you please run with -vv and share the debug log ? We can see what is adding the jobs.

mama · February 4, 2020, 2:01pm

here is the log file from this command:

rclone rcd --rc-addr=ip:port --rc-user=user --rc-pass=pass -vv

2020/02/04 13:58:42 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:42 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

2020/02/04 13:58:42 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:42 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

2020/02/04 13:58:47 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:47 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

2020/02/04 13:58:47 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:47 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

2020/02/04 13:58:52 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:52 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

2020/02/04 13:58:52 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:52 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

2020/02/04 13:58:57 DEBUG : rc: "core/stats": with parameters map[]

2020/02/04 13:58:57 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>

As you see it is just core/stats !

Animosity022 · February 4, 2020, 2:13pm

Are you running something against it to cause that? Are you checking stats every 5 seconds?

mama · February 4, 2020, 2:16pm

nothing at all I just ran rclone rcd command then sitting and watching it

Animosity022 · February 4, 2020, 2:18pm

Something is hitting it and running the core/stats command though as shown from the logs. You aren't sure what's doing that?

mama · February 4, 2020, 2:20pm

I ran rclone rcd on 3 different machines for testing and getting same result. I am sure that I am not connecting to rclone remotely in any way.

Animosity022 · February 4, 2020, 2:21pm

That's probably step 1 as something is running core/stats every 5 seconds. That should not cause high memory usage (I tested as I ran an infinite loop and did a few thousand of them and memory didn't move).

You'd need to grab a debug log when the high memory usage is going on so we can see what is running.

mama · February 4, 2020, 2:24pm

This will take about a day until reaching crash point. I will set log level and will let you know when memory usage is high
Thanks

mama · February 4, 2020, 2:43pm

here is rclone memory usage. The points that is dropped to zero was the time that we restarted it.
As you cansee it just goes up. It is not even responsible for doing any heavy task. Just sending us list of files within a specific age (about 10000 files) every 5 min. And copying about 100 folders (each 20Mb) during a period of a day.

after setting job expire duration to 2h we still have upward trend but it is not as bad as it used to be.

here is the flags that we set.

rclone rcd \

        --rc-htpasswd=rclone-rc.htpasswd \
        --rc-addr=${RCLONEIP}:5572 \
        --checkers=8 \
        --transfers=4 \
        --rc-cert=rclone-rc-certificate.pem \
        --rc-key=rclone-rc-key.pem \
        --log-file=rclone.log \
        --log-level=INFO \
        --update \
        --use-server-modtime

We also tried to reduce Buffer-size, and using use-mmap flag but no success
What is your thought

Thanks

Animosity022 · February 4, 2020, 5:03pm

Can you share the debug log and the memory dump?

https://rclone.org/rc/#debugging-memory-use