Ask for settings recommendation for azureblob

Raimondas · January 15, 2021, 2:16pm

[root@AZ1VNA01 ~]# rclone version
rclone v1.54.0-beta.5061.705d00b8b.fix-azureblob-memory
- os/arch: linux/amd64
- go version: go1.15.6

[root@AZ1VNA01 ~]# 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.042.pb.gz
File: rclone
Type: inuse_space
Time: Jan 15, 2021 at 9:15am (EST)
Showing nodes accounting for 161.81MB, 96.71% of 167.32MB total
Dropped 42 nodes (cum <= 0.84MB)
      flat  flat%   sum%        cum   cum%
   28.47MB 17.01% 17.01%    28.47MB 17.01%  bazil.org/fuse.allocMessage
      23MB 13.75% 30.76%       23MB 13.75%  github.com/rclone/rclone/vfs.newDir
   20.51MB 12.26% 43.02%    20.51MB 12.26%  github.com/Azure/azure-storage-blob-go/azblob.BlobGetPropertiesResponse.NewMetadata
       9MB  5.38% 48.40%       13MB  7.77%  github.com/rclone/rclone/vfs/vfscache.newItem
       9MB  5.38% 53.78%        9MB  5.38%  github.com/rclone/rclone/vfs.newFile
    7.50MB  4.48% 58.26%     7.50MB  4.48%  github.com/rclone/rclone/fs.NewDir (inline)
    6.50MB  3.89% 62.15%     9.50MB  5.68%  context.WithDeadline
    6.22MB  3.72% 65.86%     6.22MB  3.72%  github.com/rclone/rclone/vfs.(*Dir).addObject
       6MB  3.59% 69.45%    41.51MB 24.81%  github.com/rclone/rclone/backend/azureblob.(*Fs).Put
    5.50MB  3.29% 72.74%     5.50MB  3.29%  encoding/xml.copyValue
       5MB  2.99% 75.73%        5MB  2.99%  strings.(*Builder).grow (inline)
    4.57MB  2.73% 78.46%    28.08MB 16.78%  github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
    4.50MB  2.69% 81.15%     4.50MB  2.69%  context.(*cancelCtx).Done
       4MB  2.39% 83.54%        4MB  2.39%  sync.NewCond (inline)
       4MB  2.39% 85.93%        4MB  2.39%  net/textproto.(*Reader).ReadMIMEHeader
    3.50MB  2.09% 88.02%    31.97MB 19.11%  bazil.org/fuse.(*Conn).ReadRequest
       3MB  1.79% 89.82%        3MB  1.79%  time.AfterFunc
       3MB  1.79% 91.61%     9.72MB  5.81%  github.com/rclone/rclone/vfs.newRWFileHandle
    2.78MB  1.66% 93.27%     2.78MB  1.66%  bazil.org/fuse/fs.(*Server).saveNode
    2.50MB  1.49% 94.77%    39.48MB 23.59%  github.com/rclone/rclone/cmd/mount.(*Dir).Create
    1.50MB   0.9% 95.66%     1.50MB   0.9%  time.NewTimer
       1MB   0.6% 96.26%        1MB   0.6%  context.WithCancel
    0.75MB  0.45% 96.71%    13.75MB  8.22%  github.com/rclone/rclone/vfs/vfscache.(*Cache)._get
         0     0% 96.71%    28.47MB 17.01%  bazil.org/fuse.getMessage (inline)
         0     0% 96.71%    31.97MB 19.11%  bazil.org/fuse/fs.(*Server).Serve
         0     0% 96.71%    78.84MB 47.12%  bazil.org/fuse/fs.(*Server).Serve.func1
         0     0% 96.71%    78.84MB 47.12%  bazil.org/fuse/fs.(*Server).handleRequest
         0     0% 96.71%     2.78MB  1.66%  bazil.org/fuse/fs.(*Server).saveLookup
         0     0% 96.71%    78.84MB 47.12%  bazil.org/fuse/fs.(*Server).serve
         0     0% 96.71%     9.50MB  5.68%  context.WithTimeout
         0     0% 96.71%        1MB   0.6%  crypto/tls.(*Conn).Handshake
         0     0% 96.71%        1MB   0.6%  crypto/tls.(*Conn).clientHandshake
         0     0% 96.71%        1MB   0.6%  crypto/tls.(*clientHandshakeState).doFullHandshake
         0     0% 96.71%        1MB   0.6%  crypto/tls.(*clientHandshakeState).handshake
         0     0% 96.71%     5.50MB  3.29%  encoding/xml.(*Decoder).Decode (inline)
         0     0% 96.71%     5.50MB  3.29%  encoding/xml.(*Decoder).DecodeElement
         0     0% 96.71%     5.50MB  3.29%  encoding/xml.(*Decoder).unmarshal
         0     0% 96.71%     5.50MB  3.29%  encoding/xml.(*Decoder).unmarshalPath
         0     0% 96.71%     5.50MB  3.29%  encoding/xml.Unmarshal
         0     0% 96.71%       21MB 12.55%  github.com/Azure/azure-pipeline-go/pipeline.(*pipeline).Do
         0     0% 96.71%       21MB 12.55%  github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do
         0     0% 96.71%    11.50MB  6.87%  github.com/Azure/azure-storage-blob-go/azblob.(*SharedKeyCredential).New.func1
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).close
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).write
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).writer
         0     0% 96.71%       13MB  7.77%  github.com/Azure/azure-storage-blob-go/azblob.BlobURL.GetProperties
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.CommitBlockList
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.StageBlock
         0     0% 96.71%        6MB  3.59%  github.com/Azure/azure-storage-blob-go/azblob.ContainerURL.ListBlobsHierarchySegment
         0     0% 96.71%        6MB  3.59%  github.com/Azure/azure-storage-blob-go/azblob.NewRequestLogPolicyFactory.func1.1
         0     0% 96.71%       21MB 12.55%  github.com/Azure/azure-storage-blob-go/azblob.NewRetryPolicyFactory.func1.1
         0     0% 96.71%       21MB 12.55%  github.com/Azure/azure-storage-blob-go/azblob.NewTelemetryPolicyFactory.func1.1
         0     0% 96.71%       21MB 12.55%  github.com/Azure/azure-storage-blob-go/azblob.NewUniqueRequestIDPolicyFactory.func1.1
         0     0% 96.71%        2MB  1.20%  github.com/Azure/azure-storage-blob-go/azblob.UploadStreamToBlockBlob
         0     0% 96.71%       13MB  7.77%  github.com/Azure/azure-storage-blob-go/azblob.blobClient.GetProperties
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.CommitBlockList
         0     0% 96.71%        1MB   0.6%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.StageBlock
         0     0% 96.71%        6MB  3.59%  github.com/Azure/azure-storage-blob-go/azblob.containerClient.ListBlobHierarchySegment
         0     0% 96.71%     5.50MB  3.29%  github.com/Azure/azure-storage-blob-go/azblob.containerClient.listBlobHierarchySegmentResponder
         0     0% 96.71%        2MB  1.20%  github.com/Azure/azure-storage-blob-go/azblob.copyFromReader
         0     0% 96.71%    11.50MB  6.87%  github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do
         0     0% 96.71%       14MB  8.37%  github.com/rclone/rclone/backend/azureblob.(*Fs).List
         0     0% 96.71%        8MB  4.78%  github.com/rclone/rclone/backend/azureblob.(*Fs).itemToDirEntry
         0     0% 96.71%       14MB  8.37%  github.com/rclone/rclone/backend/azureblob.(*Fs).list
         0     0% 96.71%        6MB  3.59%  github.com/rclone/rclone/backend/azureblob.(*Fs).list.func1
         0     0% 96.71%       14MB  8.37%  github.com/rclone/rclone/backend/azureblob.(*Fs).listDir
         0     0% 96.71%        8MB  4.78%  github.com/rclone/rclone/backend/azureblob.(*Fs).listDir.func1
         0     0% 96.71%    36.01MB 21.52%  github.com/rclone/rclone/backend/azureblob.(*Object).Update
         0     0% 96.71%        2MB  1.20%  github.com/rclone/rclone/backend/azureblob.(*Object).Update.func1
         0     0% 96.71%    21.01MB 12.55%  github.com/rclone/rclone/backend/azureblob.(*Object).decodeMetaDataFromPropertiesResponse
         0     0% 96.71%    34.01MB 20.32%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData
         0     0% 96.71%       13MB  7.77%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData.func1
         0     0% 96.71%        6MB  3.59%  github.com/rclone/rclone/backend/azureblob.httpClientFactory.func1.1
         0     0% 96.71%    35.58MB 21.26%  github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
         0     0% 96.71%        1MB   0.6%  github.com/rclone/rclone/cmd/mount.(*Dir).ReadDirAll
         0     0% 96.71%    31.97MB 19.11%  github.com/rclone/rclone/cmd/mount.mount.func2
         0     0% 96.71%       21MB 12.55%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 96.71%        6MB  3.59%  github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip
         0     0% 96.71%     8.50MB  5.08%  github.com/rclone/rclone/fs/list.DirSorted
         0     0% 96.71%    41.51MB 24.81%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 96.71%       19MB 11.36%  github.com/rclone/rclone/lib/pacer.(*Pacer).Call
         0     0% 96.71%        2MB  1.20%  github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry (inline)
         0     0% 96.71%       21MB 12.55%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 96.71%     8.50MB  5.08%  github.com/rclone/rclone/vfs.(*Dir).Create
         0     0% 96.71%        1MB   0.6%  github.com/rclone/rclone/vfs.(*Dir).ReadDirAll
         0     0% 96.71%    35.58MB 21.26%  github.com/rclone/rclone/vfs.(*Dir).Stat
         0     0% 96.71%    36.58MB 21.86%  github.com/rclone/rclone/vfs.(*Dir)._readDir
         0     0% 96.71%    35.58MB 21.26%  github.com/rclone/rclone/vfs.(*Dir).stat
         0     0% 96.71%    28.48MB 17.02%  github.com/rclone/rclone/vfs.(*File).Open
         0     0% 96.71%        5MB  2.99%  github.com/rclone/rclone/vfs.(*File).Path
         0     0% 96.71%     9.72MB  5.81%  github.com/rclone/rclone/vfs.(*File).openRW
         0     0% 96.71%     6.22MB  3.72%  github.com/rclone/rclone/vfs.(*RWFileHandle).Truncate
         0     0% 96.71%     6.22MB  3.72%  github.com/rclone/rclone/vfs.(*RWFileHandle).openPending
         0     0% 96.71%    13.75MB  8.22%  github.com/rclone/rclone/vfs/vfscache.(*Cache).Exists
         0     0% 96.71%    13.75MB  8.22%  github.com/rclone/rclone/vfs/vfscache.(*Cache).get
         0     0% 96.71%    37.51MB 22.42%  github.com/rclone/rclone/vfs/vfscache.(*Item).Close.func2
         0     0% 96.71%    37.51MB 22.42%  github.com/rclone/rclone/vfs/vfscache.(*Item)._store
         0     0% 96.71%    37.51MB 22.42%  github.com/rclone/rclone/vfs/vfscache.(*Item).store
         0     0% 96.71%    37.51MB 22.42%  github.com/rclone/rclone/vfs/vfscache/writeback.(*WriteBack).upload
         0     0% 96.71%        6MB  3.59%  net/http.(*Client).Do (inline)
         0     0% 96.71%        6MB  3.59%  net/http.(*Client).do
         0     0% 96.71%        6MB  3.59%  net/http.(*Client).send
         0     0% 96.71%        6MB  3.59%  net/http.(*Transport).RoundTrip (inline)
         0     0% 96.71%        6MB  3.59%  net/http.(*Transport).roundTrip
         0     0% 96.71%        1MB   0.6%  net/http.(*persistConn).addTLS.func2
         0     0% 96.71%        4MB  2.39%  net/http.(*persistConn).readLoop
         0     0% 96.71%        4MB  2.39%  net/http.(*persistConn).readResponse
         0     0% 96.71%     1.50MB   0.9%  net/http.(*persistConn).roundTrip
         0     0% 96.71%        4MB  2.39%  net/http.ReadResponse
         0     0% 96.71%        6MB  3.59%  net/http.send
         0     0% 96.71%        5MB  2.99%  path.Join
         0     0% 96.71%     1.50MB   0.9%  runtime.doInit
         0     0% 96.71%     1.50MB   0.9%  runtime.main
         0     0% 96.71%        5MB  2.99%  strings.(*Builder).Grow (inline)
         0     0% 96.71%        5MB  2.99%  strings.Join
         0     0% 96.71%    28.47MB 17.01%  sync.(*Pool).Get

Uptime 2h

HTOP:
3266535 root 20 0 1081M 418M 31500 S 6.6 1.3 16:32.95 rclone mount --log-file=/var/log/dcmsys/rclone.log --log-level ERROR --config=/etc/rclone.conf --allow-other --default-permissions --max-read-ahead=4M --vfs-cache-mode=writes --vfs-cache-max-size=1G --azureblob-memory-pool-f

ncw · January 15, 2021, 3:06pm

That looks much better - 20MB in use by the azblob sdk.

I need this to be merged upstream before I can include it in rclone, but hopefully that will be in time for 1.54

Raimondas · January 18, 2021, 3:21pm

uptime 3 days
rclone version
rclone v1.54.0-beta.5061.705d00b8b.fix-azureblob-memory
- os/arch: linux/amd64
- go version: go1.15.6

HTOP:
3266535 root 20 0 4105M 3255M 10164 S 0.0 10.1 11h02:02 rclone mount --log-file=/var/log/dcmsys/rclone.log --log-level ERROR --config=/etc/rclone.conf --allow-other --default-permissions --max-read-ahead=4M --vfs-cache-mode=writes --vfs-ca

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.044.pb.gz
File: rclone
Type: inuse_space
Time: Jan 18, 2021 at 10:20am (EST)
Showing nodes accounting for 2586.17MB, 98.67% of 2620.96MB total
Dropped 52 nodes (cum <= 13.10MB)
      flat  flat%   sum%        cum   cum%
  451.11MB 17.21% 17.21%   451.61MB 17.23%  github.com/Azure/azure-storage-blob-go/azblob.BlobGetPropertiesResponse.NewMetadata
  325.57MB 12.42% 29.63%   406.57MB 15.51%  github.com/rclone/rclone/vfs/vfscache.newItem
  252.55MB  9.64% 39.27%   252.55MB  9.64%  github.com/rclone/rclone/vfs.newFile
  187.52MB  7.15% 46.42%   187.52MB  7.15%  context.(*cancelCtx).Done
  186.52MB  7.12% 53.54%   333.13MB 12.71%  context.WithDeadline
  184.52MB  7.04% 60.58%   184.52MB  7.04%  strings.(*Builder).grow (inline)
  159.31MB  6.08% 66.66%   159.31MB  6.08%  github.com/rclone/rclone/vfs.(*Dir).addObject
  155.01MB  5.91% 72.57%   155.01MB  5.91%  net/textproto.(*Reader).ReadMIMEHeader
  144.52MB  5.51% 78.09%  1063.71MB 40.58%  github.com/rclone/rclone/backend/azureblob.(*Fs).Put
  124.01MB  4.73% 82.82%   131.11MB  5.00%  time.AfterFunc
   88.51MB  3.38% 86.19%    88.51MB  3.38%  bazil.org/fuse.(*Conn).ReadRequest
      81MB  3.09% 89.29%       81MB  3.09%  sync.NewCond (inline)
      78MB  2.98% 92.26%   255.81MB  9.76%  github.com/rclone/rclone/vfs.newRWFileHandle
      41MB  1.56% 93.83%       41MB  1.56%  encoding/base64.(*Encoding).EncodeToString
   36.51MB  1.39% 95.22%    36.51MB  1.39%  github.com/rclone/rclone/vfs.newDir
   25.50MB  0.97% 96.19%  1112.70MB 42.45%  github.com/rclone/rclone/cmd/mount.(*Dir).Create
   22.50MB  0.86% 97.05%    35.50MB  1.35%  context.WithCancel
   18.50MB  0.71% 97.76%    18.50MB  0.71%  github.com/rclone/rclone/vfs.(*File).addWriter
   15.09MB  0.58% 98.33%    15.09MB  0.58%  time.startTimer
    8.19MB  0.31% 98.64%    43.69MB  1.67%  github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
    0.75MB 0.029% 98.67%   407.32MB 15.54%  github.com/rclone/rclone/vfs/vfscache.(*Cache)._get
         0     0% 98.67%    88.51MB  3.38%  bazil.org/fuse/fs.(*Server).Serve
         0     0% 98.67%  1192.68MB 45.51%  bazil.org/fuse/fs.(*Server).Serve.func1
         0     0% 98.67%  1192.68MB 45.51%  bazil.org/fuse/fs.(*Server).handleRequest
         0     0% 98.67%  1192.68MB 45.51%  bazil.org/fuse/fs.(*Server).serve
         0     0% 98.67%   333.13MB 12.71%  context.WithTimeout
         0     0% 98.67%    28.50MB  1.09%  context.propagateCancel
         0     0% 98.67%       15MB  0.57%  encoding/xml.(*Decoder).Decode (inline)
         0     0% 98.67%       15MB  0.57%  encoding/xml.(*Decoder).DecodeElement
         0     0% 98.67%       15MB  0.57%  encoding/xml.(*Decoder).unmarshal
         0     0% 98.67%       15MB  0.57%  encoding/xml.(*Decoder).unmarshalPath
         0     0% 98.67%       15MB  0.57%  encoding/xml.Unmarshal
         0     0% 98.67%   511.58MB 19.52%  github.com/Azure/azure-pipeline-go/pipeline.(*pipeline).Do
         0     0% 98.67%   511.58MB 19.52%  github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do
         0     0% 98.67%   178.45MB  6.81%  github.com/Azure/azure-storage-blob-go/azblob.(*SharedKeyCredential).New.func1
         0     0% 98.67%    31.55MB  1.20%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).close
         0     0% 98.67%    59.49MB  2.27%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).write
         0     0% 98.67%    59.49MB  2.27%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).writer
         0     0% 98.67%   397.53MB 15.17%  github.com/Azure/azure-storage-blob-go/azblob.BlobURL.GetProperties
         0     0% 98.67%    31.55MB  1.20%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.CommitBlockList
         0     0% 98.67%    59.49MB  2.27%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.StageBlock
         0     0% 98.67%       23MB  0.88%  github.com/Azure/azure-storage-blob-go/azblob.ContainerURL.ListBlobsHierarchySegment
         0     0% 98.67%   163.45MB  6.24%  github.com/Azure/azure-storage-blob-go/azblob.NewRequestLogPolicyFactory.func1.1
         0     0% 98.67%   511.58MB 19.52%  github.com/Azure/azure-storage-blob-go/azblob.NewRetryPolicyFactory.func1.1
         0     0% 98.67%   511.58MB 19.52%  github.com/Azure/azure-storage-blob-go/azblob.NewTelemetryPolicyFactory.func1.1
         0     0% 98.67%   511.58MB 19.52%  github.com/Azure/azure-storage-blob-go/azblob.NewUniqueRequestIDPolicyFactory.func1.1
         0     0% 98.67%    54.55MB  2.08%  github.com/Azure/azure-storage-blob-go/azblob.UploadStreamToBlockBlob
         0     0% 98.67%   397.53MB 15.17%  github.com/Azure/azure-storage-blob-go/azblob.blobClient.GetProperties
         0     0% 98.67%    31.55MB  1.20%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.CommitBlockList
         0     0% 98.67%    59.49MB  2.27%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.StageBlock
         0     0% 98.67%       23MB  0.88%  github.com/Azure/azure-storage-blob-go/azblob.containerClient.ListBlobHierarchySegment
         0     0% 98.67%       15MB  0.57%  github.com/Azure/azure-storage-blob-go/azblob.containerClient.listBlobHierarchySegmentResponder
         0     0% 98.67%    54.55MB  2.08%  github.com/Azure/azure-storage-blob-go/azblob.copyFromReader
         0     0% 98.67%   178.45MB  6.81%  github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do
         0     0% 98.67%    30.50MB  1.16%  github.com/rclone/rclone/backend/azureblob.(*Fs).List
         0     0% 98.67%       35MB  1.34%  github.com/rclone/rclone/backend/azureblob.(*Fs).list
         0     0% 98.67%       23MB  0.88%  github.com/rclone/rclone/backend/azureblob.(*Fs).list.func1
         0     0% 98.67%    31.50MB  1.20%  github.com/rclone/rclone/backend/azureblob.(*Fs).listDir
         0     0% 98.67%   944.70MB 36.04%  github.com/rclone/rclone/backend/azureblob.(*Object).Update
         0     0% 98.67%    54.55MB  2.08%  github.com/rclone/rclone/backend/azureblob.(*Object).Update.func1
         0     0% 98.67%   492.61MB 18.80%  github.com/rclone/rclone/backend/azureblob.(*Object).decodeMetaDataFromPropertiesResponse
         0     0% 98.67%   890.14MB 33.96%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData
         0     0% 98.67%   397.53MB 15.17%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData.func1
         0     0% 98.67%   163.45MB  6.24%  github.com/rclone/rclone/backend/azureblob.httpClientFactory.func1.1
         0     0% 98.67%    56.13MB  2.14%  github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
         0     0% 98.67%    88.51MB  3.38%  github.com/rclone/rclone/cmd/mount.mount.func2
         0     0% 98.67%   474.59MB 18.11%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 98.67%   163.45MB  6.24%  github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip
         0     0% 98.67%    20.50MB  0.78%  github.com/rclone/rclone/fs/list.DirSorted
         0     0% 98.67%  1080.21MB 41.21%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 98.67%   420.04MB 16.03%  github.com/rclone/rclone/lib/pacer.(*Pacer).Call
         0     0% 98.67%    54.55MB  2.08%  github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry (inline)
         0     0% 98.67%   474.59MB 18.11%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 98.67%   250.55MB  9.56%  github.com/rclone/rclone/vfs.(*Dir).Create
         0     0% 98.67%    56.13MB  2.14%  github.com/rclone/rclone/vfs.(*Dir).Stat
         0     0% 98.67%    61.69MB  2.35%  github.com/rclone/rclone/vfs.(*Dir)._readDir
         0     0% 98.67%    56.13MB  2.14%  github.com/rclone/rclone/vfs.(*Dir).stat
         0     0% 98.67%   845.66MB 32.27%  github.com/rclone/rclone/vfs.(*File).Open
         0     0% 98.67%   182.52MB  6.96%  github.com/rclone/rclone/vfs.(*File).Path
         0     0% 98.67%   255.81MB  9.76%  github.com/rclone/rclone/vfs.(*File).openRW
         0     0% 98.67%   159.31MB  6.08%  github.com/rclone/rclone/vfs.(*RWFileHandle).Truncate
         0     0% 98.67%   159.31MB  6.08%  github.com/rclone/rclone/vfs.(*RWFileHandle).openPending
         0     0% 98.67%   407.32MB 15.54%  github.com/rclone/rclone/vfs/vfscache.(*Cache).Exists
         0     0% 98.67%   407.32MB 15.54%  github.com/rclone/rclone/vfs/vfscache.(*Cache).get
         0     0% 98.67%   945.20MB 36.06%  github.com/rclone/rclone/vfs/vfscache.(*Item).Close.func2
         0     0% 98.67%   949.70MB 36.23%  github.com/rclone/rclone/vfs/vfscache.(*Item)._store
         0     0% 98.67%   945.20MB 36.06%  github.com/rclone/rclone/vfs/vfscache.(*Item).store
         0     0% 98.67%   945.20MB 36.06%  github.com/rclone/rclone/vfs/vfscache/writeback.(*WriteBack).upload
         0     0% 98.67%   163.45MB  6.24%  net/http.(*Client).Do (inline)
         0     0% 98.67%   163.45MB  6.24%  net/http.(*Client).do
         0     0% 98.67%   163.45MB  6.24%  net/http.(*Client).send
         0     0% 98.67%   163.45MB  6.24%  net/http.(*Transport).RoundTrip (inline)
         0     0% 98.67%   163.45MB  6.24%  net/http.(*Transport).roundTrip
         0     0% 98.67%   155.01MB  5.91%  net/http.(*persistConn).readLoop
         0     0% 98.67%   155.01MB  5.91%  net/http.(*persistConn).readResponse
         0     0% 98.67%   155.01MB  5.91%  net/http.ReadResponse
         0     0% 98.67%   163.45MB  6.24%  net/http.send
         0     0% 98.67%   184.02MB  7.02%  path.Join
         0     0% 98.67%   184.52MB  7.04%  strings.(*Builder).Grow (inline)
         0     0% 98.67%   184.02MB  7.02%  strings.Join

ncw · January 18, 2021, 3:23pm

Is that acceptable?

Your profile looks like you have lots of objects stored in the VFS cache - that is where the memory is being used I think.

Raimondas · January 18, 2021, 7:06pm

4Gb of ram is OK for me. I need to be sure that the memory consumption won't grow constantly without limits. If consuming won't exceed 8Gb for example, then it's ok.

ncw · January 19, 2021, 2:47pm

It is looking OK now I think

Raimondas · January 24, 2021, 8:15pm

Hi Nick,

Not really.
After 9 days of working I see that rclone uses 13Gb of RAM. Could you please recommend me what can I do in order to stop memory consumption going up? I need to have stable RAM consumption. 8Gb is OK, but not more.

uptime: 1 week 2 days

htop:

3266535 root       20   0 12.9G 12.3G 11472 S 362. 39.0 67h34:41 rclone mount --log-file=/var/log/dcmsys/rclone.log --log-level ERROR --config=/etc/rclone.conf --allow-other --default-permissions --max-read-ahead=4M --vfs-cache-mode=writes -

rclone mount --log-file=/var/log/dcmsys/rclone.log --log-level ERROR --config=/etc/rclone.conf --allow-other --default-permissions --max-read-ahead=4M --vfs-cache-mode=writes --vfs-cache-max-size=1G --azureblob-memory-pool-flush-time=1m0s --buffer-size=0 --azureblob-memory-pool-use-mmap --use-mmap --dir-cache-time=2h --timeout=1h --cache-dir=/var/dcmsys/cache --uid=1100 --gid=1100 --cache-chunk-no-memory --rc --size-only --allow-non-empty blob:studiesh /var/dcmsys/storages/GCP

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.046.pb.gz
File: rclone
Type: inuse_space
Time: Jan 24, 2021 at 2:55pm (EST)
Showing nodes accounting for 10948.52MB, 98.53% of 11111.98MB total
Dropped 200 nodes (cum <= 55.56MB)
      flat  flat%   sum%        cum   cum%
 1983.98MB 17.85% 17.85%  1984.48MB 17.86%  github.com/Azure/azure-storage-blob-go/azblob.BlobGetPropertiesResponse.NewMetadata
 1379.29MB 12.41% 30.27%  1762.82MB 15.86%  github.com/rclone/rclone/vfs/vfscache.newItem
 1133.71MB 10.20% 40.47%  1133.71MB 10.20%  github.com/rclone/rclone/vfs.newFile
  821.60MB  7.39% 47.86%   821.60MB  7.39%  strings.(*Builder).grow (inline)
  717.56MB  6.46% 54.32%  1271.10MB 11.44%  context.WithDeadline
  690.06MB  6.21% 60.53%   690.06MB  6.21%  context.(*cancelCtx).Done
  678.52MB  6.11% 66.64%   678.52MB  6.11%  net/textproto.(*Reader).ReadMIMEHeader
  674.57MB  6.07% 72.71%  4686.06MB 42.17%  github.com/rclone/rclone/backend/azureblob.(*Fs).Put
  663.85MB  5.97% 78.68%   663.85MB  5.97%  github.com/rclone/rclone/vfs.(*Dir).addObject
  525.54MB  4.73% 83.41%   539.09MB  4.85%  time.AfterFunc
  416.53MB  3.75% 87.16%   427.84MB  3.85%  bazil.org/fuse.(*Conn).ReadRequest
  407.52MB  3.67% 90.83%  1156.83MB 10.41%  github.com/rclone/rclone/vfs.newRWFileHandle
  382.52MB  3.44% 94.27%   382.52MB  3.44%  sync.NewCond (inline)
  194.51MB  1.75% 96.02%   194.51MB  1.75%  encoding/base64.(*Encoding).EncodeToString
   93.50MB  0.84% 96.86%  4940.71MB 44.46%  github.com/rclone/rclone/cmd/mount.(*Dir).Create
      86MB  0.77% 97.64%       86MB  0.77%  github.com/rclone/rclone/vfs.(*File).addWriter
      61MB  0.55% 98.18%       61MB  0.55%  time.startTimer
      33MB   0.3% 98.48%    61.50MB  0.55%  context.WithCancel
    1.25MB 0.011% 98.49%  1764.07MB 15.88%  github.com/rclone/rclone/vfs/vfscache.(*Cache)._get
       1MB 0.009% 98.50%   702.46MB  6.32%  github.com/Azure/azure-storage-blob-go/azblob.(*SharedKeyCredential).New.func1
       1MB 0.009% 98.51%   119.52MB  1.08%  github.com/Azure/azure-storage-blob-go/azblob.copyFromReader
       1MB 0.009% 98.52%  5066.74MB 45.60%  bazil.org/fuse/fs.(*Server).handleRequest
       1MB 0.009% 98.53%  1769.09MB 15.92%  github.com/Azure/azure-storage-blob-go/azblob.blobClient.GetProperties
         0     0% 98.53%   427.84MB  3.85%  bazil.org/fuse/fs.(*Server).Serve
         0     0% 98.53%  5067.24MB 45.60%  bazil.org/fuse/fs.(*Server).Serve.func1
         0     0% 98.53%  5067.24MB 45.60%  bazil.org/fuse/fs.(*Server).serve
         0     0% 98.53%  1271.10MB 11.44%  context.WithTimeout
         0     0% 98.53%    57.01MB  0.51%  context.propagateCancel
         0     0% 98.53%  1978.06MB 17.80%  github.com/Azure/azure-pipeline-go/pipeline.(*pipeline).Do
         0     0% 98.53%  1976.56MB 17.79%  github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do
         0     0% 98.53%    70.51MB  0.63%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).close
         0     0% 98.53%    98.45MB  0.89%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).write
         0     0% 98.53%    98.45MB  0.89%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).writer
         0     0% 98.53%  1769.09MB 15.92%  github.com/Azure/azure-storage-blob-go/azblob.BlobURL.GetProperties
         0     0% 98.53%    70.51MB  0.63%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.CommitBlockList
         0     0% 98.53%    98.45MB  0.89%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.StageBlock
         0     0% 98.53%   674.45MB  6.07%  github.com/Azure/azure-storage-blob-go/azblob.NewRequestLogPolicyFactory.func1.1
         0     0% 98.53%  1976.06MB 17.78%  github.com/Azure/azure-storage-blob-go/azblob.NewRetryPolicyFactory.func1.1
         0     0% 98.53%  1976.56MB 17.79%  github.com/Azure/azure-storage-blob-go/azblob.NewTelemetryPolicyFactory.func1.1
         0     0% 98.53%  1976.56MB 17.79%  github.com/Azure/azure-storage-blob-go/azblob.NewUniqueRequestIDPolicyFactory.func1.1
         0     0% 98.53%   119.52MB  1.08%  github.com/Azure/azure-storage-blob-go/azblob.UploadStreamToBlockBlob
         0     0% 98.53%    70.51MB  0.63%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.CommitBlockList
         0     0% 98.53%    98.45MB  0.89%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.StageBlock
         0     0% 98.53%   698.45MB  6.29%  github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do
         0     0% 98.53%    60.51MB  0.54%  github.com/rclone/rclone/backend/azureblob.(*Fs).list
         0     0% 98.53%  4062.49MB 36.56%  github.com/rclone/rclone/backend/azureblob.(*Object).Update
         0     0% 98.53%   119.52MB  1.08%  github.com/rclone/rclone/backend/azureblob.(*Object).Update.func1
         0     0% 98.53%  2178.48MB 19.60%  github.com/rclone/rclone/backend/azureblob.(*Object).decodeMetaDataFromPropertiesResponse
         0     0% 98.53%  3930.63MB 35.37%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData
         0     0% 98.53%  1769.09MB 15.92%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData.func1
         0     0% 98.53%   674.45MB  6.07%  github.com/rclone/rclone/backend/azureblob.httpClientFactory.func1.1
         0     0% 98.53%    69.14MB  0.62%  github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
         0     0% 98.53%   427.84MB  3.85%  github.com/rclone/rclone/cmd/mount.mount.func2
         0     0% 98.53%  1933.11MB 17.40%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 98.53%   672.95MB  6.06%  github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip
         0     0% 98.53%  4717.06MB 42.45%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 98.53%  1813.10MB 16.32%  github.com/rclone/rclone/lib/pacer.(*Pacer).Call
         0     0% 98.53%   118.52MB  1.07%  github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry (inline)
         0     0% 98.53%  1933.11MB 17.40%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 98.53%  1131.21MB 10.18%  github.com/rclone/rclone/vfs.(*Dir).Create
         0     0% 98.53%    69.14MB  0.62%  github.com/rclone/rclone/vfs.(*Dir).Stat
         0     0% 98.53%    77.70MB   0.7%  github.com/rclone/rclone/vfs.(*Dir)._readDir
         0     0% 98.53%    69.14MB  0.62%  github.com/rclone/rclone/vfs.(*Dir).stat
         0     0% 98.53%  3732.50MB 33.59%  github.com/rclone/rclone/vfs.(*File).Open
         0     0% 98.53%   811.60MB  7.30%  github.com/rclone/rclone/vfs.(*File).Path
         0     0% 98.53%  1156.83MB 10.41%  github.com/rclone/rclone/vfs.(*File).openRW
         0     0% 98.53%   663.33MB  5.97%  github.com/rclone/rclone/vfs.(*RWFileHandle).Truncate
         0     0% 98.53%   663.33MB  5.97%  github.com/rclone/rclone/vfs.(*RWFileHandle).openPending
         0     0% 98.53%  1764.07MB 15.88%  github.com/rclone/rclone/vfs/vfscache.(*Cache).Exists
         0     0% 98.53%  1764.07MB 15.88%  github.com/rclone/rclone/vfs/vfscache.(*Cache).get
         0     0% 98.53%  4125.51MB 37.13%  github.com/rclone/rclone/vfs/vfscache.(*Item).Close.func2
         0     0% 98.53%  4132.51MB 37.19%  github.com/rclone/rclone/vfs/vfscache.(*Item)._store
         0     0% 98.53%  4125.51MB 37.13%  github.com/rclone/rclone/vfs/vfscache.(*Item).store
         0     0% 98.53%  4125.51MB 37.13%  github.com/rclone/rclone/vfs/vfscache/writeback.(*WriteBack).upload
         0     0% 98.53%   674.45MB  6.07%  net/http.(*Client).Do (inline)
         0     0% 98.53%   674.45MB  6.07%  net/http.(*Client).do
         0     0% 98.53%   672.95MB  6.06%  net/http.(*Client).send
         0     0% 98.53%   672.95MB  6.06%  net/http.(*Transport).RoundTrip (inline)
         0     0% 98.53%   672.95MB  6.06%  net/http.(*Transport).roundTrip
         0     0% 98.53%   679.02MB  6.11%  net/http.(*persistConn).readLoop
         0     0% 98.53%   679.02MB  6.11%  net/http.(*persistConn).readResponse
         0     0% 98.53%   679.02MB  6.11%  net/http.ReadResponse
         0     0% 98.53%   672.95MB  6.06%  net/http.send
         0     0% 98.53%   818.60MB  7.37%  path.Join
         0     0% 98.53%   821.60MB  7.39%  strings.(*Builder).Grow (inline)
         0     0% 98.53%   821.10MB  7.39%  strings.Join

Best,
Raymond

ncw · January 25, 2021, 10:27am

What you can see in this memory profile is that the memory is used by the VFS cache.

So it looks like the azure blob SDK leak is fixed, but you have a lot of cached items in the VFS cache.

I think this is the same issue as

How many items do you have in the VFS cache?

Raimondas · January 25, 2021, 10:34am

I used following options:
dir-cache-time=2h
vfs-cache-max-size=1G
Now I'll try to use:
vfs-cache-max-size=100M

Anyway, in the cache directory I see thousands of empty folders/subfolders. Is it possible that rclone is not deleting empty folders after using/caching? I believe it is the root of the problem.
Is it possible to limit not just size but number of object allowed to keep in vfs cache?

Best,
Raymond

ncw · January 25, 2021, 10:51am

How many objects do you have?

Rclone deletes empty folders, but only on startup.

Not yet, that is what the above issue is for.

Raimondas · January 25, 2021, 11:13am

Right now I have 20770759 files uploaded with about 197298 folders used (total size=12.88 TB).
After restarting rclone I found 154306 objects (files/folders/subfolders) in vfs cache with 124512K size. I believe rclone removed old files/folders during start-up.

As a work-around, is it safe to run a custom script to walk through the vfs cache and delete an old and empty folders? What are the consequences? May it solve the memory consumption?
How to disable vfs cache completely?

Best,
Raymond

ncw · January 25, 2021, 12:13pm

OK, that is a lot!

So at minimum rclone cached 154,306 objects, but likely more since it will have cached the directories these objects are in.

Great

It is reasonably safe. Stuff might go wrong if you hit the point just after rclone has done mkdir and before it has created a file. You can use rclone rmdirs to delete all the empty directories recursively - that is what rclone uses internally.

I don't think that will solve the memory problem. It is the objects cached in memory that is the problem, not the stuff on disk.

What should solve the problem is to call vfs/forget - this can flush the cache of objects and reclaim the memory used by them. It won't lower the RSS of the process but it should stop it getting bigger.

You could do that at regular intervals.

Can you give that a try?

Raimondas · January 25, 2021, 3:28pm

It's only a fracture of the data we are going to upload. Final size might take up to 400Tb.

You can use rclone rmdirs to delete all the empty directories recursively - that is what rclone uses internally.

rclone rc vfs/forget

If the main program rclone is running in the background, allowing access to the cloud storage mounted, is it safe/possible to execute in parallel commands:
rclone rc vfs/forget
rclone rmdirs
to clean up the vfs cache folder?

ncw · January 26, 2021, 11:26am

Yes vfs/forget is safe

rclone rmdirs is less safe - best to do it at a time when people aren't creating files.

If you please make a new issue on github about the build up of folders in the cache directory, then I'll fix it properly as part of the cache cleaning. It will require a bit of internal locking but it isn't a big deal.

Raimondas · January 26, 2021, 5:39pm

done.

Also I've created a small script in crontab to search and remove old (3 days old) empty folders in vfs cache:

find /var/vfscache/ -type d -ctime +3 -empty -print0| xargs -0 -I {} /bin/rmdir "{}"
/usr/bin/rclone rc vfs/forget > /dev/null 2>&1

BTW. when I ran rclone rc vfs/forget I didn't mention any memory improvements. rclone used exactly the same amount of memory before and after this command.

ncw · January 26, 2021, 10:31pm

You should see a difference if you do the memory dump.

The go runtime is very slow about giving memory back to the OS, but you should see the memory used in the dump is lower which means go won't need to ask for more.

Thanks for making the issue.

Raimondas · February 7, 2021, 8:00pm

uptime: 1 week 2 days

Nick, looks like the version you gave me is stable. The script to clean up the memory and old folders helped also. Thank you very much!

Uploaded so far: images=36238921; size=20.28 TB

I have one question. In log file I see errors like:
Failed to copy: context canceled
corrupted on transfer: MD5 hash differ "d41d8cd98f00b204e9800998ecf8427e" vs "e3d4bc86f501d5e7e108711612b52e23"
vfs cache: failed to upload try #1, will retry in 10s: vfs cache: failed to transfer file from cache to remote: corrupted on transfer: MD5 hash differ "d41d8cd98f00b204e9800998ecf8427e" vs "e3d4bc86f501d5e7e108711612b52e23"
Failed to copy: -> github.com/Azure/azure-pipeline-go/pipeline.NewError, github.com/Azure/azure-pipeline-go@v0.2.3/pipeline/error.go:157

Are they important and may corrupt the final files?

2251570 root       20   0 7496M 5999M 12340 S 12.6 18.7 85h23:40 rclone mount --log-file=/var/log/dcmsys/rclone.log --log-level ERROR --config=/etc/rclone.conf --allow-other --default-permissions --max-read-ahead=4M --vfs-cache-mode=writes --vfs-

rclone version
rclone v1.54.0-beta.5061.705d00b8b.fix-azureblob-memory
- os/arch: linux/amd64
- go version: go1.15.6


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.052.pb.gz
File: rclone
Type: inuse_space
Time: Feb 7, 2021 at 2:57pm (EST)
Showing nodes accounting for 4737.06MB, 97.26% of 4870.35MB total
Dropped 158 nodes (cum <= 24.35MB)
      flat  flat%   sum%        cum   cum%
 1679.64MB 34.49% 34.49%  2964.84MB 60.88%  context.WithDeadline
 1462.63MB 30.03% 64.52%  1462.63MB 30.03%  context.(*cancelCtx).Done
 1221.59MB 25.08% 89.60%  1254.70MB 25.76%  time.AfterFunc
  132.44MB  2.72% 92.32%   132.44MB  2.72%  time.startTimer
   77.51MB  1.59% 93.91%    77.51MB  1.59%  github.com/rclone/rclone/vfs.newDir
   38.50MB  0.79% 94.70%    65.50MB  1.34%  context.WithCancel
   30.50MB  0.63% 95.33%    30.50MB  0.63%  github.com/rclone/rclone/fs.NewDir (inline)
   25.50MB  0.52% 95.85%    25.50MB  0.52%  encoding/xml.copyValue
   24.51MB   0.5% 96.36%    24.51MB   0.5%  github.com/Azure/azure-storage-blob-go/azblob.BlobGetPropertiesResponse.NewMetadata
   19.23MB  0.39% 96.75%    84.74MB  1.74%  github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
   13.50MB  0.28% 97.03%   112.83MB  2.32%  time.NewTimer
       9MB  0.18% 97.21%  4017.56MB 82.49%  github.com/rclone/rclone/backend/azureblob.(*Fs).Put
       1MB 0.021% 97.23%    57.51MB  1.18%  context.propagateCancel
       1MB 0.021% 97.25%    54.18MB  1.11%  github.com/rclone/rclone/cmd/mount.(*Dir).Create
    0.50MB  0.01% 97.26%   211.34MB  4.34%  github.com/Azure/azure-storage-blob-go/azblob.copyFromReader
         0     0% 97.26%   241.09MB  4.95%  bazil.org/fuse/fs.(*Server).Serve.func1
         0     0% 97.26%   241.09MB  4.95%  bazil.org/fuse/fs.(*Server).handleRequest
         0     0% 97.26%   241.09MB  4.95%  bazil.org/fuse/fs.(*Server).serve
         0     0% 97.26%  2963.84MB 60.85%  context.WithTimeout
         0     0% 97.26%    29.50MB  0.61%  encoding/xml.(*Decoder).Decode (inline)
         0     0% 97.26%    29.50MB  0.61%  encoding/xml.(*Decoder).DecodeElement
         0     0% 97.26%    29.50MB  0.61%  encoding/xml.(*Decoder).unmarshal
         0     0% 97.26%    29.50MB  0.61%  encoding/xml.(*Decoder).unmarshalPath
         0     0% 97.26%    29.50MB  0.61%  encoding/xml.Unmarshal
         0     0% 97.26%  4517.34MB 92.75%  github.com/Azure/azure-pipeline-go/pipeline.(*pipeline).Do
         0     0% 97.26%  4517.34MB 92.75%  github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do
         0     0% 97.26%  1552.49MB 31.88%  github.com/Azure/azure-storage-blob-go/azblob.(*SharedKeyCredential).New.func1
         0     0% 97.26%   165.34MB  3.39%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).close
         0     0% 97.26%    96.01MB  1.97%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).write
         0     0% 97.26%    96.01MB  1.97%  github.com/Azure/azure-storage-blob-go/azblob.(*copier).writer
         0     0% 97.26%  4157.95MB 85.37%  github.com/Azure/azure-storage-blob-go/azblob.BlobURL.GetProperties
         0     0% 97.26%   165.34MB  3.39%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.CommitBlockList
         0     0% 97.26%    96.01MB  1.97%  github.com/Azure/azure-storage-blob-go/azblob.BlockBlobURL.StageBlock
         0     0% 97.26%    99.54MB  2.04%  github.com/Azure/azure-storage-blob-go/azblob.ContainerURL.ListBlobsHierarchySegment
         0     0% 97.26%  1521.46MB 31.24%  github.com/Azure/azure-storage-blob-go/azblob.NewRequestLogPolicyFactory.func1.1
         0     0% 97.26%  4517.34MB 92.75%  github.com/Azure/azure-storage-blob-go/azblob.NewRetryPolicyFactory.func1.1
         0     0% 97.26%  4517.34MB 92.75%  github.com/Azure/azure-storage-blob-go/azblob.NewTelemetryPolicyFactory.func1.1
         0     0% 97.26%  4517.34MB 92.75%  github.com/Azure/azure-storage-blob-go/azblob.NewUniqueRequestIDPolicyFactory.func1.1
         0     0% 97.26%   211.34MB  4.34%  github.com/Azure/azure-storage-blob-go/azblob.UploadStreamToBlockBlob
         0     0% 97.26%  4157.95MB 85.37%  github.com/Azure/azure-storage-blob-go/azblob.blobClient.GetProperties
         0     0% 97.26%   165.34MB  3.39%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.CommitBlockList
         0     0% 97.26%    96.01MB  1.97%  github.com/Azure/azure-storage-blob-go/azblob.blockBlobClient.StageBlock
         0     0% 97.26%    99.54MB  2.04%  github.com/Azure/azure-storage-blob-go/azblob.containerClient.ListBlobHierarchySegment
         0     0% 97.26%    30.03MB  0.62%  github.com/Azure/azure-storage-blob-go/azblob.containerClient.listBlobHierarchySegmentResponder
         0     0% 97.26%  1551.49MB 31.86%  github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do
         0     0% 97.26%   117.51MB  2.41%  github.com/rclone/rclone/backend/azureblob.(*Fs).List
         0     0% 97.26%   121.51MB  2.49%  github.com/rclone/rclone/backend/azureblob.(*Fs).list
         0     0% 97.26%    99.54MB  2.04%  github.com/rclone/rclone/backend/azureblob.(*Fs).list.func1
         0     0% 97.26%   117.51MB  2.41%  github.com/rclone/rclone/backend/azureblob.(*Fs).listDir
         0     0% 97.26%  4298.58MB 88.26%  github.com/rclone/rclone/backend/azureblob.(*Object).Update
         0     0% 97.26%   210.84MB  4.33%  github.com/rclone/rclone/backend/azureblob.(*Object).Update.func1
         0     0% 97.26%    27.01MB  0.55%  github.com/rclone/rclone/backend/azureblob.(*Object).decodeMetaDataFromPropertiesResponse
         0     0% 97.26%  4151.85MB 85.25%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData
         0     0% 97.26%  4157.95MB 85.37%  github.com/rclone/rclone/backend/azureblob.(*Object).readMetaData.func1
         0     0% 97.26%  1521.46MB 31.24%  github.com/rclone/rclone/backend/azureblob.httpClientFactory.func1.1
         0     0% 97.26%   156.75MB  3.22%  github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
         0     0% 97.26%  4401.61MB 90.38%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 97.26%  1519.96MB 31.21%  github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip
         0     0% 97.26%    92.01MB  1.89%  github.com/rclone/rclone/fs/list.DirSorted
         0     0% 97.26%  4278.08MB 87.84%  github.com/rclone/rclone/fs/operations.Copy
         0     0% 97.26%  4256.46MB 87.40%  github.com/rclone/rclone/lib/pacer.(*Pacer).Call
         0     0% 97.26%   142.62MB  2.93%  github.com/rclone/rclone/lib/pacer.(*Pacer).CallNoRetry (inline)
         0     0% 97.26%  4401.61MB 90.38%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 97.26%   156.75MB  3.22%  github.com/rclone/rclone/vfs.(*Dir).Stat
         0     0% 97.26%   157.75MB  3.24%  github.com/rclone/rclone/vfs.(*Dir)._readDir
         0     0% 97.26%   156.75MB  3.22%  github.com/rclone/rclone/vfs.(*Dir).stat
         0     0% 97.26%    41.18MB  0.85%  github.com/rclone/rclone/vfs.(*File).Open
         0     0% 97.26%  2933.46MB 60.23%  github.com/rclone/rclone/vfs/vfscache.(*Item).Close.func2
         0     0% 97.26%  3017.46MB 61.96%  github.com/rclone/rclone/vfs/vfscache.(*Item)._store
         0     0% 97.26%  2933.46MB 60.23%  github.com/rclone/rclone/vfs/vfscache.(*Item).store
         0     0% 97.26%  2933.46MB 60.23%  github.com/rclone/rclone/vfs/vfscache/writeback.(*WriteBack).upload
         0     0% 97.26%  1521.46MB 31.24%  net/http.(*Client).Do (inline)
         0     0% 97.26%  1521.46MB 31.24%  net/http.(*Client).do
         0     0% 97.26%  1519.96MB 31.21%  net/http.(*Client).send
         0     0% 97.26%  1519.96MB 31.21%  net/http.(*Transport).RoundTrip (inline)
         0     0% 97.26%  1519.96MB 31.21%  net/http.(*Transport).roundTrip
         0     0% 97.26%   112.83MB  2.32%  net/http.(*persistConn).roundTrip
         0     0% 97.26%  1519.96MB 31.21%  net/http.send

ncw · February 7, 2021, 9:03pm

Excellent! The changes went into 1.54 so you should be able to use that.

Raimondas:

1679.64MB 34.49% 34.49%  2964.84MB 60.88%  context.WithDeadline
 1462.63MB 30.03% 64.52%  1462.63MB 30.03%  context.(*cancelCtx).Done
 1221.59MB 25.08% 89.60%  1254.70MB 25.76%  time.AfterFunc

Something is leaking timers here...

Can you send me the .gz file the pprof generates and I'll analyze further. You can attach here, but if it is too big then email to nick@craig-wood.com

This normally means the file changed during upload. The VFS layer should retry it so it shouldn't lead to corrupted data.

ncw · February 8, 2021, 5:07pm

Thanks for the pprof .gz file. I've opened a new upstream issue here:

system · April 10, 2021, 1:07pm

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