Rclone constantly increasing vsz

Help and Support
1

hi there,
I am using a gdrive encrypted volume with rclone

rclone --version
rclone v1.52.3

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

on a Qnap NAS, here is my mount command line

rclone
--config rclone.conf
--daemon
--rc
--fast-list
--buffer-size 10M
--umask 000
--stats 0
--allow-non-empty
--allow-other
--use-mmap
--retries 5
--log-level INFO
--vfs-cache-mode minimal
--checkers 8
--log-file=rclone.log
mount gdriveEncrypted:/ /share/gdriveEnrypted
</dev/null >/dev/null 2>&1

everything works fine... until it doesn't. From time to time the NAS get sluggish until I have to reboot it, and I noticed that the problem is it's madly swapping, usually the 8GB ram are more than enough, furterly investigating I found that the rclone mount uses even 80% of VSZ, even if no file is opened in the mountpoint (checked with lsof).

I am closely watching this and I noticed that, when I mount the volume rclone uses less than 10% VSZ, but from time to time this number can only increase, until it blocks everything.

here is the detail of profile tool

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.rclone.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
File: rclone
Type: inuse_space
Time: Sep 6, 2020 at 8:50am (CEST)
Showing nodes accounting for 9505.41kB, 100% of 9505.41kB total
flat flat% sum% cum cum%
1536.20kB 16.16% 16.16% 1536.20kB 16.16% github.com/rclone/rclone/vfs.newDir
1536.17kB 16.16% 32.32% 1536.17kB 16.16% strings.(*Builder).grow (inline)
1187.31kB 12.49% 44.81% 3235.61kB 34.04% github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
1144.17kB 12.04% 56.85% 1144.17kB 12.04% github.com/rclone/rclone/vendor/bazil.org/fuse/fs.(*Server).saveNode
1024.51kB 10.78% 67.63% 1024.51kB 10.78% github.com/rclone/rclone/vendor/github.com/aws/aws-sdk-go/aws/endpoints.init
516.64kB 5.44% 73.06% 516.64kB 5.44% github.com/rclone/rclone/vendor/github.com/gogo/protobuf/proto.RegisterType
512.19kB 5.39% 78.45% 512.19kB 5.39% runtime.malg
512.11kB 5.39% 83.84% 512.11kB 5.39% github.com/rclone/rclone/vfs.newFile
512.05kB 5.39% 89.23% 512.05kB 5.39% regexp/syntax.(*parser).newRegexp (inline)
512.05kB 5.39% 94.61% 512.05kB 5.39% fmt.Sprintf
512.02kB 5.39% 100% 512.02kB 5.39% encoding/json.(*decodeState).literalStore
0 0% 100% 512.02kB 5.39% encoding/json.(*Decoder).Decode
0 0% 100% 512.02kB 5.39% encoding/json.(*decodeState).array
0 0% 100% 512.02kB 5.39% encoding/json.(*decodeState).object
0 0% 100% 512.02kB 5.39% encoding/json.(*decodeState).unmarshal
0 0% 100% 512.02kB 5.39% encoding/json.(*decodeState).value
0 0% 100% 2560.23kB 26.93% github.com/rclone/rclone/backend/crypt.(*Fs).List
0 0% 100% 2560.23kB 26.93% github.com/rclone/rclone/backend/drive.(*Fs).List
0 0% 100% 2048.22kB 21.55% github.com/rclone/rclone/backend/drive.(*Fs).List.func1
0 0% 100% 512.05kB 5.39% github.com/rclone/rclone/backend/drive.(*Fs).itemToDirEntry
0 0% 100% 2560.23kB 26.93% github.com/rclone/rclone/backend/drive.(*Fs).list
0 0% 100% 512.02kB 5.39% github.com/rclone/rclone/backend/drive.(*Fs).list.func1
0 0% 100% 512.05kB 5.39% github.com/rclone/rclone/backend/drive.(*Fs).newObjectWithInfo
0 0% 100% 512.05kB 5.39% github.com/rclone/rclone/backend/drive.(*Fs).newRegularObject
0 0% 100% 512.05kB 5.39% github.com/rclone/rclone/backend/googlephotos.dirPatterns.mustCompile
0 0% 100% 512.05kB 5.39% github.com/rclone/rclone/backend/googlephotos.init
0 0% 100% 5795.84kB 60.97% github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
0 0% 100% 512.02kB 5.39% github.com/rclone/rclone/fs.pacerInvoker
0 0% 100% 2560.23kB 26.93% github.com/rclone/rclone/fs/list.DirSorted
0 0% 100% 512.02kB 5.39% github.com/rclone/rclone/lib/pacer.(*Pacer).Call
0 0% 100% 512.02kB 5.39% github.com/rclone/rclone/lib/pacer.(*Pacer).call
0 0% 100% 6940.02kB 73.01% github.com/rclone/rclone/vendor/bazil.org/fuse/fs.(*Server).Serve.func1
0 0% 100% 6940.02kB 73.01% github.com/rclone/rclone/vendor/bazil.org/fuse/fs.(*Server).handleRequest
0 0% 100% 1144.17kB 12.04% github.com/rclone/rclone/vendor/bazil.org/fuse/fs.(*Server).saveLookup
0 0% 100% 6940.02kB 73.01% github.com/rclone/rclone/vendor/bazil.org/fuse/fs.(*Server).serve
0 0% 100% 512.02kB 5.39% github.com/rclone/rclone/vendor/google.golang.org/api/drive/v3.(*FilesListCall).Do
0 0% 100% 512.02kB 5.39% github.com/rclone/rclone/vendor/google.golang.org/api/internal/gensupport.DecodeResponse (inline)
0 0% 100% 516.64kB 5.44% github.com/rclone/rclone/vendor/storj.io/common/pb.init.18
0 0% 100% 5795.84kB 60.97% github.com/rclone/rclone/vfs.(*Dir).Stat
0 0% 100% 5795.84kB 60.97% github.com/rclone/rclone/vfs.(*Dir)._readDir
0 0% 100% 5795.84kB 60.97% github.com/rclone/rclone/vfs.(*Dir).stat
0 0% 100% 1536.17kB 16.16% path.Join
0 0% 100% 512.05kB 5.39% regexp.Compile (inline)
0 0% 100% 512.05kB 5.39% regexp.MustCompile
0 0% 100% 512.05kB 5.39% regexp.compile
0 0% 100% 512.05kB 5.39% regexp/syntax.Parse
0 0% 100% 2053.20kB 21.60% runtime.doInit
0 0% 100% 2053.20kB 21.60% runtime.main
0 0% 100% 512.19kB 5.39% runtime.mstart
0 0% 100% 512.19kB 5.39% runtime.newproc.func1
0 0% 100% 512.19kB 5.39% runtime.newproc1
0 0% 100% 512.19kB 5.39% runtime.systemstack
0 0% 100% 1536.17kB 16.16% strings.(*Builder).Grow (inline)
0 0% 100% 1536.17kB 16.16% strings.Join

I will updated it as the % increases. Hope this is enough so that you can help me understand how to avoid this issue.
Thanks in advance

2

hello,

  • --fast-list does nothing on a mount

  • --checkers, pretty does nothing on a mount

  • --allow-non-empty - never saw a post that did not recommend to remove.

  • the latest stable v1.53.0, has a major update to mount and its vfs cache

3

ok, I will follow your suggestions and update rclone version, I will keep watching %VSZ and keep you posted

4

upgraded to last version, this is after a few hours: 26.9% of VSZ and

Fetching profile over HTTP from http://localhost:5572/debug/pprof/heap
Saved profile in /root/pprof/pprof.rclone.alloc_objects.alloc_space.inuse_objects.inuse_space.007.pb.gz
File: rclone
Type: inuse_space
Time: Sep 7, 2020 at 12:41am (CEST)
Showing nodes accounting for 1068.19MB, 99.48% of 1073.79MB total
Dropped 50 nodes (cum <= 5.37MB)
flat flat% sum% cum cum%
474.76MB 44.21% 44.21% 474.76MB 44.21% strings.(*Builder).grow (inline)
128.02MB 11.92% 56.14% 128.02MB 11.92% github.com/rclone/rclone/vfs.newFile
105MB 9.78% 65.91% 105MB 9.78% encoding/json.(*decodeState).literalStore
93.94MB 8.75% 74.66% 93.94MB 8.75% bazil.org/fuse.allocMessage
72.51MB 6.75% 81.42% 139.51MB 12.99% github.com/rclone/rclone/backend/drive.(*Fs).newRegularObject
67.01MB 6.24% 87.66% 67.01MB 6.24% fmt.Sprintf
52.41MB 4.88% 92.54% 302.46MB 28.17% github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
23MB 2.14% 94.68% 23MB 2.14% github.com/rclone/rclone/backend/crypt.(*Fs).newObject (inline)
15.50MB 1.44% 96.12% 15.50MB 1.44% github.com/rclone/rclone/vfs.newDir
11.50MB 1.07% 97.19% 133.70MB 12.45% github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
9.03MB 0.84% 98.03% 9.03MB 0.84% github.com/rclone/rclone/lib/dircache.(*DirCache).Put
9MB 0.84% 98.87% 9MB 0.84% bazil.org/fuse/fs.(*Server).saveNode
6.50MB 0.61% 99.48% 6.50MB 0.61% github.com/rclone/rclone/fs.NewDirCopy
0 0% 99.48% 93.94MB 8.75% bazil.org/fuse.(*Conn).ReadRequest
0 0% 99.48% 93.94MB 8.75% bazil.org/fuse.getMessage (inline)
0 0% 99.48% 93.94MB 8.75% bazil.org/fuse/fs.(*Server).Serve
0 0% 99.48% 976.34MB 90.92% bazil.org/fuse/fs.(*Server).Serve.func1
0 0% 99.48% 976.34MB 90.92% bazil.org/fuse/fs.(*Server).handleRequest
0 0% 99.48% 9MB 0.84% bazil.org/fuse/fs.(*Server).saveLookup
0 0% 99.48% 976.34MB 90.92% bazil.org/fuse/fs.(*Server).serve
0 0% 99.48% 105.50MB 9.83% encoding/json.(*Decoder).Decode
0 0% 99.48% 105MB 9.78% encoding/json.(*decodeState).array
0 0% 99.48% 105.50MB 9.83% encoding/json.(*decodeState).object
0 0% 99.48% 105.50MB 9.83% encoding/json.(*decodeState).unmarshal
0 0% 99.48% 105.50MB 9.83% encoding/json.(*decodeState).value
0 0% 99.48% 16MB 1.49% github.com/rclone/rclone/backend/crypt.(*Cipher).DecryptDirName
0 0% 99.48% 106.52MB 9.92% github.com/rclone/rclone/backend/crypt.(*Cipher).DecryptFileName
0 0% 99.48% 122.53MB 11.41% github.com/rclone/rclone/backend/crypt.(*Cipher).decryptFileName
0 0% 99.48% 650.29MB 60.56% github.com/rclone/rclone/backend/crypt.(*Fs).List
0 0% 99.48% 23MB 2.14% github.com/rclone/rclone/backend/crypt.(*Fs).add
0 0% 99.48% 22.50MB 2.10% github.com/rclone/rclone/backend/crypt.(*Fs).addDir
0 0% 99.48% 45.50MB 4.24% github.com/rclone/rclone/backend/crypt.(*Fs).encryptEntries
0 0% 99.48% 22.50MB 2.10% github.com/rclone/rclone/backend/crypt.(*Fs).newDir
0 0% 99.48% 106.52MB 9.92% github.com/rclone/rclone/backend/crypt.(*Object).Remote
0 0% 99.48% 604.78MB 56.32% github.com/rclone/rclone/backend/drive.(*Fs).List
0 0% 99.48% 499.78MB 46.54% github.com/rclone/rclone/backend/drive.(*Fs).List.func1
0 0% 99.48% 148.55MB 13.83% github.com/rclone/rclone/backend/drive.(*Fs).itemToDirEntry
0 0% 99.48% 604.78MB 56.32% github.com/rclone/rclone/backend/drive.(*Fs).list
0 0% 99.48% 105MB 9.78% github.com/rclone/rclone/backend/drive.(*Fs).list.func1
0 0% 99.48% 139.51MB 12.99% github.com/rclone/rclone/backend/drive.(*Fs).newObjectWithInfo
0 0% 99.48% 831.54MB 77.44% github.com/rclone/rclone/cmd/mount.(*Dir).ReadDirAll
0 0% 99.48% 93.94MB 8.75% github.com/rclone/rclone/cmd/mount.mount.func2
0 0% 99.48% 105.50MB 9.83% github.com/rclone/rclone/fs.pacerInvoker
0 0% 99.48% 650.29MB 60.56% github.com/rclone/rclone/fs/list.DirSorted
0 0% 99.48% 105.50MB 9.83% github.com/rclone/rclone/lib/pacer.(*Pacer).Call
0 0% 99.48% 105.50MB 9.83% github.com/rclone/rclone/lib/pacer.(*Pacer).call
0 0% 99.48% 831.54MB 77.44% github.com/rclone/rclone/vfs.(*Dir).ReadDirAll
0 0% 99.48% 122.20MB 11.38% github.com/rclone/rclone/vfs.(*Dir).Stat
0 0% 99.48% 952.74MB 88.73% github.com/rclone/rclone/vfs.(*Dir)._readDir
0 0% 99.48% 122.20MB 11.38% github.com/rclone/rclone/vfs.(*Dir).stat
0 0% 99.48% 105MB 9.78% google.golang.org/api/drive/v3.(*FilesListCall).Do
0 0% 99.48% 105.50MB 9.83% google.golang.org/api/internal/gensupport.DecodeResponse (inline)
0 0% 99.48% 352.23MB 32.80% path.Join
0 0% 99.48% 474.76MB 44.21% strings.(*Builder).Grow (inline)
0 0% 99.48% 474.76MB 44.21% strings.Join
0 0% 99.48% 93.94MB 8.75% sync.(*Pool).Get

5

How many files do you have in your mount?

What it looks like is the VFS metadata cache is getting too big.

There is an issue about this I think...

And here is another thread about what I think is the same problem

6

od only knows how many files... I use the mount for backup and there is a lot of stuff with big files and many many many very small files

7

Can you quantify that? 1,000? 10,000? 1,000,000? 10,000,000?

8

I am inclined to think that 10M is the order of size, but when you backup an android sdk installation or the AppData directory of a windows laptop is hard to say... it just takes a lot of time.
I can try to count them

9

Just a simple rclone size gdriveEncrypted: will give you the required info.

10

With 10M files and the way the dir-cache works, it makes sense it's going to use quite a bit of memory once it walks the full set of files.

11

Yeah, I know, hence the earlier created GH issue. I was just mentioning an easy way to get the actual count of files instead of guessing about it.

EDIT: On a second read, you probably meant to reply to n3urale instead of me.

12

Yep, I know that you know that I know that you that issue was created by you and I did actually mean to reply to the OP rather than you as you know that i know that too :slight_smile:

13

I was very wrong:

Total objects: 1824907
Total size: 100.080 TBytes (110038635165379 Bytes)

14

That is a lot of files. I think it is almost certain that this is caused be the issues I linked.

I will try to fix this in the 1.54 Dev cycle

1 Like
15

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