Rclone mount high load average

cberni · May 24, 2022, 3:20am

What is the problem you are having with rclone?

load average: 145.08, 202.39, 121.21

sometimes the load average increases a lot. Looking at the -vv log below I just clipped the error messages. If I restart the mount manually everything goes back to normal including load average.

I suspect the firewall is blocking some packets. And rclone cannot download these packages again. Any way to improve this usage? or any other way to debbug it?

Run the command 'rclone version' and share the full output of the command.

rclone v1.58.1

os/version: ubuntu 20.04 (64 bit)
os/kernel: 5.4.0-105-generic (x86_64)
os/type: linux
os/arch: amd64
go/version: go1.17.9
go/linking: static
go/tags: none

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

google cloud storage

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

rclone mount remote:bucket /remote --rc --use-mmap

The rclone config contents with secrets removed.

[remote]
type = google cloud storage
service_account_file =

A log from the command with the `-vv` flag

2022/05/23 15:04:06 DEBUG : pacer: low level retry 7/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2022%2F1%2F19%2F11%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:08 DEBUG : pacer: low level retry 7/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2022%2F1%2F19%2F14%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:10 DEBUG : pacer: low level retry 1/10 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket/o/pacs-data%2Fuploaded-images%2F202205%2F1652816188144.jpg?generation=1652816193434764&alt=media": http2: timeout awaiting response headers)
2022/05/23 15:04:12 DEBUG : pacer: low level retry 2/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2021%2F11%2F29%2F12%2F9A7E354A%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:14 DEBUG : pacer: low level retry 2/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2020%2F9%2F23%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:16 DEBUG : pacer: low level retry 8/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2021%2F11%2F26%2F10%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:18 DEBUG : pacer: low level retry 7/10 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket/o/pacs-data%2Farchive%2F2019%2F11%2F4%2F10%2FB1E1A079%2F1DE9321D%2F9CEF7592?generation=1589818988649367&alt=media": http2: timeout awaiting response headers)
2022/05/23 15:04:20 DEBUG : pacer: low level retry 6/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2020%2F1%2F10%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:22 DEBUG : pacer: low level retry 4/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2018%2F11%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:24 DEBUG : pacer: low level retry 7/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2019%2F10%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/05/23 15:04:26 DEBUG : pacer: low level retry 8/10 (error Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2021%2F10%2F6%2F&prettyPrint=false": http2: timeout awaiting response headers)

and

2022/05/23 15:00:10 ERROR : archive/2019/10/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2019%2F10%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:00:18 ERROR : archive/2017/2/13/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2017%2F2%2F13%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:01:28 ERROR : archive/2021/7/20/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2021%2F7%2F20%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:01:32 ERROR : uploaded-images/202201/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Fuploaded-images%2F202201%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:01:48 ERROR : archive/2018/11/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2018%2F11%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:02:04 ERROR : uploaded-images/202001/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Fuploaded-images%2F202001%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:02:50 ERROR : archive/2021/11/29/12/9A7E354A/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2021%2F11%2F29%2F12%2F9A7E354A%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/05/23 15:02:52 ERROR : archive/2020/9/23/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2020%2F9%2F23%2F&prettyPrint=false": http2: timeout awaiting response headers

ncw · May 24, 2022, 8:54am

Does look like something went wrong with networking.

Check connectivity to storage.googleapis.com

cberni · May 24, 2022, 11:24am

Yes. we encounter connection problems. However it is a place that does not depend on us for this to be good. I set --low-level-retries = 1 but it keeps causing high load. Is there any other flag to clear or return an error to the requestor? any way to reduce the load even with the internet fails for seconds? in this case it is doing read-only...

Animosity022 · May 24, 2022, 11:38am

Load is based on the IO being unable to process due to the network issues you are seeing.

Fix the network issue, load will go down.

Have a network issue, load will go up.

You can't tune around that.

cberni · June 14, 2022, 6:32pm

today we are having google internet instabilities. see attachment..

so we are getting several timeouts like the logs posted before and below:

2022/05/30 11:57:57 ERROR : archive/2019/10/28/9/28739660/BF6CD1E0/23E1384E: ReadFileHandle.Read error: low level retry 1/10: read tcp 192.168.60.19:53444->142.251.129.176:443: i/o timeout
2022/05/30 18:21:44 ERROR : archive/2022/1/7/15/93F2EE17/E94F5FAF/E94F6EF1: ReadFileHandle.Read error: low level retry 1/10: read tcp 192.168.60.19:53158->142.250.219.144:443: i/o timeout

the main problem is that get more or less 10 files with timeout and after the the second try It start to get very high load average. I tried to set --low-level-retries 1 but also get high load avererage with just fews timeouts.

Than just restart the service mount and all get back to normal very quickly. Load average comes back to 5 instead 205.

Also set --contimeout 30s and --timeout 60s and same problem. Is there any other timeout? or what could we do to avoid high load averege caused by rclone? when the load average goes up the rest of the system is affected.

Animosity022 · June 14, 2022, 6:46pm

Network timeouts are generally always going to break network mounts and resort in an unstable system.

cberni · June 14, 2022, 6:52pm

in this case rclone is just secondary to get some old files. We need something that doesn't affect everything else in the system. Something that makes you reject immediately and not wait.

Animosity022 · June 14, 2022, 7:22pm

Unmount the disk to prevent access to it until the network stabilizes and remount it?

You aren't going to tune around this as a network mount wants a working network.

cberni · June 15, 2022, 12:25am

maybe there is a bug becouse network comes back to normal and rclone keep giving timeout for the the same especific files. another files works ok. and this especific files timeout is enough to get high load average.

ncw · June 15, 2022, 8:51am

Is rclone giving lots of CPU load? If so then attach the profiler as per here: Remote Control / API then it will show exactly what is using the CPU which will help diagnosing.

Animosity022 · June 15, 2022, 10:52am

It's not CPU load.

It's system load.

System load goes up when the network mount has issue/times out as that's expected behavior.

cberni · June 15, 2022, 11:48am

yes. but the main problem is that have some fail and the log keep trying timeout. If restart the mount all comes back to normal. I'm waiting to happen again to get the debug.

Animosity022 · June 15, 2022, 12:28pm

That's generally exactly what I'd expect to happen as once the network stabilizes, a restart would fix anything hung underneath.

Not trying to repeat myself, but a network mount expects a network and you won't be able to tune around as you have to deal with the fall out.

cberni · June 23, 2022, 1:07pm

high load average...

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: Jun 23, 2022 at 10:05am (-03)
Showing nodes accounting for 518.49MB, 97.86% of 529.83MB total
Dropped 77 nodes (cum <= 2.65MB)
      flat  flat%   sum%        cum   cum%
  173.52MB 32.75% 32.75%   173.52MB 32.75%  encoding/json.(*decodeState).literalStore
  113.52MB 21.43% 54.18%   113.52MB 21.43%  github.com/rclone/rclone/vfs.newFile
   68.01MB 12.84% 67.01%    88.51MB 16.70%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).newObjectWithInfo
   59.01MB 11.14% 78.15%    59.01MB 11.14%  github.com/rclone/rclone/vfs.newDir
   55.11MB 10.40% 88.55%   227.14MB 42.87%  github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
   20.50MB  3.87% 92.42%    20.50MB  3.87%  encoding/hex.EncodeToString (inline)
      16MB  3.02% 95.44%       16MB  3.02%  github.com/rclone/rclone/fs.NewDir (inline)
    6.26MB  1.18% 96.62%     6.26MB  1.18%  bazil.org/fuse.allocMessage
       3MB  0.57% 97.19%   508.17MB 95.91%  github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
    2.50MB  0.47% 97.66%        3MB  0.57%  github.com/rclone/rclone/vfs/vfscache.newItem
    1.05MB   0.2% 97.86%     4.05MB  0.77%  github.com/rclone/rclone/vfs/vfscache.(*Cache)._get
         0     0% 97.86%     6.26MB  1.18%  bazil.org/fuse.(*Conn).ReadRequest
         0     0% 97.86%     6.26MB  1.18%  bazil.org/fuse.getMessage (inline)
         0     0% 97.86%     6.26MB  1.18%  bazil.org/fuse/fs.(*Server).Serve
         0     0% 97.86%   514.97MB 97.20%  bazil.org/fuse/fs.(*Server).Serve.func1
         0     0% 97.86%   514.97MB 97.20%  bazil.org/fuse/fs.(*Server).handleRequest
         0     0% 97.86%   514.97MB 97.20%  bazil.org/fuse/fs.(*Server).serve
         0     0% 97.86%   173.52MB 32.75%  encoding/json.(*Decoder).Decode
         0     0% 97.86%   173.52MB 32.75%  encoding/json.(*decodeState).array
         0     0% 97.86%   173.52MB 32.75%  encoding/json.(*decodeState).object
         0     0% 97.86%   173.52MB 32.75%  encoding/json.(*decodeState).unmarshal
         0     0% 97.86%   173.52MB 32.75%  encoding/json.(*decodeState).value
         0     0% 97.86%   278.03MB 52.48%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).List
         0     0% 97.86%   104.51MB 19.73%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).itemToDirEntry
         0     0% 97.86%   278.03MB 52.48%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).list
         0     0% 97.86%   173.52MB 32.75%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).list.func1
         0     0% 97.86%   278.03MB 52.48%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).listDir
         0     0% 97.86%   104.51MB 19.73%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).listDir.func1
         0     0% 97.86%    20.50MB  3.87%  github.com/rclone/rclone/backend/googlecloudstorage.(*Object).setMetaData
         0     0% 97.86%     4.55MB  0.86%  github.com/rclone/rclone/cmd/mount.(*File).Open
         0     0% 97.86%     6.26MB  1.18%  github.com/rclone/rclone/cmd/mount.mount.func2
         0     0% 97.86%   173.52MB 32.75%  github.com/rclone/rclone/fs.pacerInvoker
         0     0% 97.86%   278.03MB 52.48%  github.com/rclone/rclone/fs/list.DirSorted
         0     0% 97.86%   173.52MB 32.75%  github.com/rclone/rclone/lib/pacer.(*Pacer).Call
         0     0% 97.86%   173.52MB 32.75%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0% 97.86%   505.17MB 95.35%  github.com/rclone/rclone/vfs.(*Dir).Stat
         0     0% 97.86%   505.17MB 95.35%  github.com/rclone/rclone/vfs.(*Dir)._readDir
         0     0% 97.86%   505.17MB 95.35%  github.com/rclone/rclone/vfs.(*Dir).stat
         0     0% 97.86%     5.05MB  0.95%  github.com/rclone/rclone/vfs.(*File).Open
         0     0% 97.86%     4.05MB  0.77%  github.com/rclone/rclone/vfs/vfscache.(*Cache).Exists
         0     0% 97.86%     4.05MB  0.77%  github.com/rclone/rclone/vfs/vfscache.(*Cache).get
         0     0% 97.86%   173.52MB 32.75%  google.golang.org/api/internal/gensupport.DecodeResponse (inline)
         0     0% 97.86%   173.52MB 32.75%  google.golang.org/api/storage/v1.(*ObjectsListCall).Do
         0     0% 97.86%     4.57MB  0.86%  runtime.doInit
         0     0% 97.86%     4.57MB  0.86%  runtime.main
         0     0% 97.86%     6.26MB  1.18%  sync.(*Pool).Get

ncw · June 23, 2022, 1:15pm

Can you do a CPU profile instead of a memory profile?

go tool pprof http://localhost:5572/debug/pprof/profile

cberni · June 27, 2022, 1:33pm

load average: 157.10, 206.82, 138.13

go tool pprof -text http://localhost:5572/debug/pprof/profile

Fetching profile over HTTP from http://localhost:5572/debug/pprof/profile
Saved profile in /root/pprof/pprof.rclone.samples.cpu.005.pb.gz
File: rclone
Type: cpu
Time: Jun 27, 2022 at 10:28am (-03)
Duration: 30s, Total samples = 1.83s ( 6.10%)
Showing nodes accounting for 1.83s, 100% of 1.83s total
      flat  flat%   sum%        cum   cum%
     0.47s 25.68% 25.68%      0.50s 27.32%  syscall.Syscall
     0.12s  6.56% 32.24%      0.12s  6.56%  runtime.memclrNoHeapPointers
     0.10s  5.46% 37.70%      0.10s  5.46%  runtime.futex
     0.09s  4.92% 42.62%      0.09s  4.92%  runtime.epollwait
     0.08s  4.37% 46.99%      0.08s  4.37%  crypto/aes.gcmAesDec
     0.06s  3.28% 50.27%      0.06s  3.28%  runtime.memmove
     0.03s  1.64% 51.91%      0.03s  1.64%  runtime.(*itabTableType).find
     0.03s  1.64% 53.55%      0.07s  3.83%  runtime.newobject (partial-inline)
     0.02s  1.09% 54.64%      0.02s  1.09%  crypto/md5.block
     0.02s  1.09% 55.74%      0.31s 16.94%  github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Read
     0.02s  1.09% 56.83%      0.02s  1.09%  runtime.(*mcache).prepareForSweep
     0.02s  1.09% 57.92%      0.06s  3.28%  runtime.adjustframe
     0.02s  1.09% 59.02%      0.02s  1.09%  runtime.casgstatus
     0.02s  1.09% 60.11%      0.02s  1.09%  runtime.checkTimers
     0.02s  1.09% 61.20%      0.02s  1.09%  runtime.isSystemGoroutine
     0.02s  1.09% 62.30%      0.02s  1.09%  runtime.nextFreeFast (inline)
     0.02s  1.09% 63.39%      0.03s  1.64%  runtime.pcvalue
     0.02s  1.09% 64.48%      0.02s  1.09%  runtime.stackalloc
     0.02s  1.09% 65.57%      0.02s  1.09%  runtime.step
     0.01s  0.55% 66.12%      0.01s  0.55%  aeshashbody
     0.01s  0.55% 66.67%      0.12s  6.56%  bazil.org/fuse/fs.(*Server).Serve
     0.01s  0.55% 67.21%      0.82s 44.81%  bazil.org/fuse/fs.(*Server).handleRequest
     0.01s  0.55% 67.76%      0.84s 45.90%  bazil.org/fuse/fs.(*Server).serve
     0.01s  0.55% 68.31%      0.01s  0.55%  crypto/aes.gcmAesData
     0.01s  0.55% 68.85%      0.08s  4.37%  crypto/tls.(*Conn).Write
     0.01s  0.55% 69.40%      0.01s  0.55%  fmt.(*fmt).fmtInteger
     0.01s  0.55% 69.95%      0.16s  8.74%  fmt.(*pp).doPrintf
     0.01s  0.55% 70.49%      0.08s  4.37%  fmt.(*pp).handleMethods
     0.01s  0.55% 71.04%      0.15s  8.20%  fmt.(*pp).printArg
     0.01s  0.55% 71.58%      0.04s  2.19%  fmt.(*pp).printValue
     0.01s  0.55% 72.13%      0.04s  2.19%  github.com/rclone/rclone/vfs.(*File).Open
     0.01s  0.55% 72.68%      0.06s  3.28%  github.com/rclone/rclone/vfs.(*ReadFileHandle).openPending
     0.01s  0.55% 73.22%      0.01s  0.55%  github.com/rclone/rclone/vfs/vfscache.(*Cache).InUse
     0.01s  0.55% 73.77%      0.01s  0.55%  net/http.(*http2ClientConn).forgetStreamID
     0.01s  0.55% 74.32%      0.45s 24.59%  net/http.(*http2Framer).ReadFrame
     0.01s  0.55% 74.86%      0.02s  1.09%  net/http.(*http2clientStream).cleanupWriteRequest
     0.01s  0.55% 75.41%      0.06s  3.28%  net/http.glob..func5
     0.01s  0.55% 75.96%      0.04s  2.19%  net/http.http2transportResponseBody.Read
     0.01s  0.55% 76.50%      0.02s  1.09%  net/url.parse
     0.01s  0.55% 77.05%      0.01s  0.55%  path.(*lazybuf).append (inline)
     0.01s  0.55% 77.60%      0.01s  0.55%  reflect.Value.Elem
     0.01s  0.55% 78.14%      0.01s  0.55%  reflect.Value.IsNil (inline)
     0.01s  0.55% 78.69%      0.01s  0.55%  reflect.Value.OverflowInt (inline)
     0.01s  0.55% 79.23%      0.01s  0.55%  reflect.typedmemmove
     0.01s  0.55% 79.78%      0.12s  6.56%  runtime.(*mcentral).cacheSpan
     0.01s  0.55% 80.33%      0.01s  0.55%  runtime.(*mspan).nextFreeIndex
     0.01s  0.55% 80.87%      0.01s  0.55%  runtime.(*pageAlloc).alloc
     0.01s  0.55% 81.42%      0.01s  0.55%  runtime.(*pageCache).alloc
     0.01s  0.55% 81.97%      0.01s  0.55%  runtime.(*pallocBits).find1 (inline)
     0.01s  0.55% 82.51%      0.01s  0.55%  runtime.(*randomEnum).next (inline)
     0.01s  0.55% 83.06%      0.01s  0.55%  runtime.adjustpointer (inline)
     0.01s  0.55% 83.61%      0.01s  0.55%  runtime.convI2I
     0.01s  0.55% 84.15%      0.02s  1.09%  runtime.convT2E
     0.01s  0.55% 84.70%      0.01s  0.55%  runtime.divRoundUp (inline)
     0.01s  0.55% 85.25%      0.01s  0.55%  runtime.duffcopy
     0.01s  0.55% 85.79%      0.01s  0.55%  runtime.fastrand (inline)
     0.01s  0.55% 86.34%      0.01s  0.55%  runtime.findfunc
     0.01s  0.55% 86.89%      0.03s  1.64%  runtime.funcMaxSPDelta
     0.01s  0.55% 87.43%      0.09s  4.92%  runtime.gentraceback
     0.01s  0.55% 87.98%      0.03s  1.64%  runtime.getStackMap
     0.01s  0.55% 88.52%      0.01s  0.55%  runtime.heapBitsForAddr (inline)
     0.01s  0.55% 89.07%      0.01s  0.55%  runtime.mapaccess2_fast64
     0.01s  0.55% 89.62%      0.02s  1.09%  runtime.mapassign_faststr
     0.01s  0.55% 90.16%      0.01s  0.55%  runtime.nanotime (inline)
     0.01s  0.55% 90.71%      0.10s  5.46%  runtime.netpoll
     0.01s  0.55% 91.26%      0.06s  3.28%  runtime.newproc.func1
     0.01s  0.55% 91.80%      0.13s  7.10%  runtime.newstack
     0.01s  0.55% 92.35%      0.02s  1.09%  runtime.pcdatavalue
     0.01s  0.55% 92.90%      0.01s  0.55%  runtime.pidleget
     0.01s  0.55% 93.44%      0.02s  1.09%  runtime.runqgrab
     0.01s  0.55% 93.99%      0.05s  2.73%  runtime.stealWork
     0.01s  0.55% 94.54%      0.01s  0.55%  runtime.usleep
     0.01s  0.55% 95.08%      0.01s  0.55%  runtime.wirep
     0.01s  0.55% 95.63%      0.01s  0.55%  strconv.appendQuotedWith
     0.01s  0.55% 96.17%      0.01s  0.55%  strings.Trim
     0.01s  0.55% 96.72%      0.02s  1.09%  sync.(*Mutex).Unlock
     0.01s  0.55% 97.27%      0.01s  0.55%  sync.(*Pool).pin
     0.01s  0.55% 97.81%      0.01s  0.55%  sync.loadPoolChainElt (inline)
     0.01s  0.55% 98.36%      0.01s  0.55%  syscall.Syscall6
     0.01s  0.55% 98.91%      0.01s  0.55%  time.Time.abs
     0.01s  0.55% 99.45%      0.01s  0.55%  time.Until
     0.01s  0.55%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.huffmanDecode
         0     0%   100%      0.05s  2.73%  bazil.org/fuse.(*Conn).ReadRequest
         0     0%   100%      0.03s  1.64%  bazil.org/fuse.(*Conn).respond
         0     0%   100%      0.03s  1.64%  bazil.org/fuse.(*Conn).writeToKernel
         0     0%   100%      0.01s  0.55%  bazil.org/fuse.(*FlushRequest).Respond
         0     0%   100%      0.03s  1.64%  bazil.org/fuse.(*Header).respond
         0     0%   100%      0.06s  3.28%  bazil.org/fuse.(*ReadRequest).Respond
         0     0%   100%      0.01s  0.55%  bazil.org/fuse.(*ReleaseRequest).Respond
         0     0%   100%      0.01s  0.55%  bazil.org/fuse.getMessage (inline)
         0     0%   100%      0.05s  2.73%  bazil.org/fuse.newBuffer (inline)
         0     0%   100%      0.84s 45.90%  bazil.org/fuse/fs.(*Server).Serve.func1
         0     0%   100%      0.02s  1.09%  bazil.org/fuse/fs.(*Server).saveLookup
         0     0%   100%      0.02s  1.09%  bazil.org/fuse/fs.(*Server).serve.func1
         0     0%   100%      0.05s  2.73%  bazil.org/fuse/fs.(*serveNode).attr (inline)
         0     0%   100%      0.07s  3.83%  bazil.org/fuse/fs.nodeAttr
         0     0%   100%      0.43s 23.50%  bufio.(*Reader).Read
         0     0%   100%      0.08s  4.37%  bufio.(*Writer).Flush
         0     0%   100%      0.31s 16.94%  bytes.(*Buffer).ReadFrom
         0     0%   100%      0.01s  0.55%  bytes.(*Reader).Read (inline)
         0     0%   100%      0.03s  1.64%  context.WithCancel
         0     0%   100%      0.08s  4.37%  crypto/aes.(*gcmAsm).Open
         0     0%   100%      0.01s  0.55%  crypto/aes.(*gcmAsm).Seal
         0     0%   100%      0.02s  1.09%  crypto/md5.(*digest).Write
         0     0%   100%      0.03s  1.64%  crypto/tls.(*Conn).Handshake (inline)
         0     0%   100%      0.03s  1.64%  crypto/tls.(*Conn).HandshakeContext (inline)
         0     0%   100%      0.43s 23.50%  crypto/tls.(*Conn).Read
         0     0%   100%      0.03s  1.64%  crypto/tls.(*Conn).handshakeContext
         0     0%   100%      0.31s 16.94%  crypto/tls.(*Conn).readFromUntil
         0     0%   100%      0.39s 21.31%  crypto/tls.(*Conn).readRecord (inline)
         0     0%   100%      0.39s 21.31%  crypto/tls.(*Conn).readRecordOrCCS
         0     0%   100%      0.05s  2.73%  crypto/tls.(*Conn).write
         0     0%   100%      0.06s  3.28%  crypto/tls.(*Conn).writeRecordLocked
         0     0%   100%      0.31s 16.94%  crypto/tls.(*atLeastReader).Read
         0     0%   100%      0.08s  4.37%  crypto/tls.(*halfConn).decrypt
         0     0%   100%      0.01s  0.55%  crypto/tls.(*halfConn).encrypt
         0     0%   100%      0.08s  4.37%  crypto/tls.(*xorNonceAEAD).Open
         0     0%   100%      0.01s  0.55%  crypto/tls.(*xorNonceAEAD).Seal
         0     0%   100%      0.03s  1.64%  encoding/json.(*Decoder).Decode
         0     0%   100%      0.03s  1.64%  encoding/json.(*decodeState).array
         0     0%   100%      0.01s  0.55%  encoding/json.(*decodeState).literalInterface
         0     0%   100%      0.02s  1.09%  encoding/json.(*decodeState).literalStore
         0     0%   100%      0.03s  1.64%  encoding/json.(*decodeState).object
         0     0%   100%      0.03s  1.64%  encoding/json.(*decodeState).unmarshal
         0     0%   100%      0.03s  1.64%  encoding/json.(*decodeState).value
         0     0%   100%      0.01s  0.55%  encoding/json.(*decodeState).valueQuoted
         0     0%   100%      0.01s  0.55%  fmt.(*fmt).fmtQ
         0     0%   100%      0.01s  0.55%  fmt.(*pp).fmtInteger
         0     0%   100%      0.02s  1.09%  fmt.(*pp).fmtString
         0     0%   100%      0.01s  0.55%  fmt.(*pp).free
         0     0%   100%      0.18s  9.84%  fmt.Sprintf
         0     0%   100%      0.01s  0.55%  github.com/prometheus/client_golang/prometheus.(*CounterVec).GetMetricWithLabelValues (inline)
         0     0%   100%      0.01s  0.55%  github.com/prometheus/client_golang/prometheus.(*CounterVec).WithLabelValues
         0     0%   100%      0.01s  0.55%  github.com/prometheus/client_golang/prometheus.(*MetricVec).GetMetricWithLabelValues
         0     0%   100%      0.01s  0.55%  github.com/prometheus/client_golang/prometheus.(*metricMap).getMetricWithHashAndLabelValues
         0     0%   100%      0.01s  0.55%  github.com/prometheus/client_golang/prometheus.(*metricMap).getOrCreateMetricWithLabelValues
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).List
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).itemToDirEntry
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).list
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).list.func1
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).listDir
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/backend/googlecloudstorage.(*Fs).listDir.func1
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/backend/googlecloudstorage.(*Object).Open
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/backend/googlecloudstorage.(*Object).Open.func1
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/cmd/mount.(*Dir).Attr
         0     0%   100%      0.10s  5.46%  github.com/rclone/rclone/cmd/mount.(*Dir).Lookup
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/cmd/mount.(*File).Attr
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/cmd/mount.(*File).Open
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/cmd/mount.(*FileHandle).Flush
         0     0%   100%      0.26s 14.21%  github.com/rclone/rclone/cmd/mount.(*FileHandle).Read
         0     0%   100%      0.09s  4.92%  github.com/rclone/rclone/cmd/mount.(*FileHandle).Release
         0     0%   100%      0.12s  6.56%  github.com/rclone/rclone/cmd/mount.mount.func2
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/fs.Debugf
         0     0%   100%      0.29s 15.85%  github.com/rclone/rclone/fs.LogPrintf
         0     0%   100%      0.14s  7.65%  github.com/rclone/rclone/fs.glob..func4
         0     0%   100%      0.05s  2.73%  github.com/rclone/rclone/fs.pacerInvoker
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/fs/accounting.(*Account).Close
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/fs/accounting.(*Account).Read
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/fs/accounting.(*Account).read
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/fs/accounting.(*StatsInfo).PruneTransfers
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/fs/accounting.(*StatsInfo).removeTransfer
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/fs/accounting.(*Transfer).Done
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/fs/chunkedreader.(*ChunkedReader).Close
         0     0%   100%      0.05s  2.73%  github.com/rclone/rclone/fs/chunkedreader.(*ChunkedReader).Open
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/fs/chunkedreader.(*ChunkedReader).Read
         0     0%   100%      0.05s  2.73%  github.com/rclone/rclone/fs/chunkedreader.(*ChunkedReader).openRange
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/fs/chunkedreader.(*ChunkedReader).resetReader
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/fs/fshttp.(*Metrics).onResponse
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/fs/fshttp.(*Transport).RoundTrip
         0     0%   100%      0.05s  2.73%  github.com/rclone/rclone/fs/fshttp.(*timeoutConn).Write
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/fs/fshttp.(*timeoutConn).nudgeDeadline
         0     0%   100%      0.02s  1.09%  github.com/rclone/rclone/fs/hash.(*MultiHasher).Write (inline)
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/fs/list.DirSorted
         0     0%   100%      0.18s  9.84%  github.com/rclone/rclone/fs/log.Trace
         0     0%   100%      0.12s  6.56%  github.com/rclone/rclone/fs/log.Trace.func2
         0     0%   100%      0.03s  1.64%  github.com/rclone/rclone/fs/log.fnName
         0     0%   100%      0.05s  2.73%  github.com/rclone/rclone/lib/pacer.(*Pacer).Call
         0     0%   100%      0.05s  2.73%  github.com/rclone/rclone/lib/pacer.(*Pacer).call
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/vfs.(*Dir).Stat
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/vfs.(*Dir)._readDir
         0     0%   100%      0.02s  1.09%  github.com/rclone/rclone/vfs.(*Dir)._readDirFromEntries
         0     0%   100%      0.06s  3.28%  github.com/rclone/rclone/vfs.(*Dir).stat
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*File).ModTime
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*File).Path
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*File).Size
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*File).String (inline)
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*File)._path (inline)
         0     0%   100%      0.14s  7.65%  github.com/rclone/rclone/vfs.(*ReadFileHandle).ReadAt
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/vfs.(*ReadFileHandle).Release
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*ReadFileHandle).String
         0     0%   100%      0.04s  2.19%  github.com/rclone/rclone/vfs.(*ReadFileHandle).close
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs.(*ReadFileHandle).close.func1
         0     0%   100%      0.14s  7.65%  github.com/rclone/rclone/vfs.(*ReadFileHandle).readAt
         0     0%   100%      0.02s  1.09%  github.com/rclone/rclone/vfs.manageVirtuals.add
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs/vfscache.(*Cache).DirtyItem
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs/vfscache.(*Cache).Exists
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs/vfscache.(*Item).Exists
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs/vfscache.(*Item)._exists
         0     0%   100%      0.01s  0.55%  github.com/rclone/rclone/vfs/vfscache.clean
         0     0%   100%      0.01s  0.55%  golang.org/x/oauth2.(*Transport).RoundTrip
         0     0%   100%      0.03s  1.64%  google.golang.org/api/internal/gensupport.DecodeResponse (inline)
         0     0%   100%      0.03s  1.64%  google.golang.org/api/storage/v1.(*ObjectsListCall).Do
         0     0%   100%      0.28s 15.30%  internal/poll.(*FD).Read
         0     0%   100%      0.01s  0.55%  internal/poll.(*FD).SetDeadline (inline)
         0     0%   100%      0.15s  8.20%  internal/poll.(*FD).Write
         0     0%   100%      0.43s 23.50%  internal/poll.ignoringEINTRIO (inline)
         0     0%   100%      0.01s  0.55%  internal/poll.setDeadlineImpl
         0     0%   100%      0.02s  1.09%  io.(*multiWriter).Write
         0     0%   100%      0.49s 26.78%  io.ReadAtLeast
         0     0%   100%      0.49s 26.78%  io.ReadFull (inline)
         0     0%   100%      0.11s  6.01%  log.(*Logger).Output
         0     0%   100%      0.01s  0.55%  log.(*Logger).formatHeader
         0     0%   100%      0.11s  6.01%  log.Output (inline)
         0     0%   100%      0.28s 15.30%  net.(*conn).Read
         0     0%   100%      0.01s  0.55%  net.(*conn).SetDeadline
         0     0%   100%      0.05s  2.73%  net.(*conn).Write
         0     0%   100%      0.28s 15.30%  net.(*netFD).Read
         0     0%   100%      0.01s  0.55%  net.(*netFD).SetDeadline (inline)
         0     0%   100%      0.05s  2.73%  net.(*netFD).Write
         0     0%   100%      0.01s  0.55%  net/http.(*Client).Do (inline)
         0     0%   100%      0.01s  0.55%  net/http.(*Client).do
         0     0%   100%      0.01s  0.55%  net/http.(*Client).send
         0     0%   100%      0.02s  1.09%  net/http.(*http2ClientConn).encodeHeaders
         0     0%   100%      0.01s  0.55%  net/http.(*http2ClientConn).encodeHeaders.func1
         0     0%   100%      0.01s  0.55%  net/http.(*http2ClientConn).encodeHeaders.func3
         0     0%   100%      0.55s 30.05%  net/http.(*http2ClientConn).readLoop
         0     0%   100%      0.01s  0.55%  net/http.(*http2ClientConn).writeHeader
         0     0%   100%      0.02s  1.09%  net/http.(*http2ClientConn).writeHeaders
         0     0%   100%      0.01s  0.55%  net/http.(*http2Framer).readMetaFrame
         0     0%   100%      0.01s  0.55%  net/http.(*http2clientConnReadLoop).handleResponse
         0     0%   100%      0.08s  4.37%  net/http.(*http2clientConnReadLoop).processData
         0     0%   100%      0.01s  0.55%  net/http.(*http2clientConnReadLoop).processHeaders
         0     0%   100%      0.01s  0.55%  net/http.(*http2clientConnReadLoop).processPing
         0     0%   100%      0.55s 30.05%  net/http.(*http2clientConnReadLoop).run
         0     0%   100%      0.06s  3.28%  net/http.(*http2clientStream).doRequest
         0     0%   100%      0.04s  2.19%  net/http.(*http2clientStream).encodeAndWriteHeaders
         0     0%   100%      0.04s  2.19%  net/http.(*http2clientStream).writeRequest
         0     0%   100%      0.01s  0.55%  net/http.(*http2dataBuffer).Read
         0     0%   100%      0.06s  3.28%  net/http.(*http2dataBuffer).Write
         0     0%   100%      0.06s  3.28%  net/http.(*http2dataBuffer).lastChunkOrAlloc
         0     0%   100%      0.01s  0.55%  net/http.(*http2pipe).Read
         0     0%   100%      0.07s  3.83%  net/http.(*http2pipe).Write
         0     0%   100%      0.02s  1.09%  net/http.NewRequestWithContext
         0     0%   100%      0.06s  3.28%  net/http.http2getDataBufferChunk
         0     0%   100%      0.33s 18.03%  net/http.http2readFrameHeader
         0     0%   100%      0.08s  4.37%  net/http.http2stickyErrWriter.Write
         0     0%   100%      0.03s  1.64%  net/http.http2transportResponseBody.Close
         0     0%   100%      0.01s  0.55%  net/http.send
         0     0%   100%      0.01s  0.55%  net/url.(*URL).RequestURI
         0     0%   100%      0.02s  1.09%  net/url.Parse
         0     0%   100%      0.10s  5.46%  os.(*File).Write
         0     0%   100%      0.10s  5.46%  os.(*File).write (inline)
         0     0%   100%      0.01s  0.55%  os.Stat
         0     0%   100%      0.01s  0.55%  os.ignoringEINTR (inline)
         0     0%   100%      0.01s  0.55%  os.statNolog
         0     0%   100%      0.01s  0.55%  os.statNolog.func1 (inline)
         0     0%   100%      0.01s  0.55%  path.Clean
         0     0%   100%      0.02s  1.09%  path.Join
         0     0%   100%      0.01s  0.55%  reflect.Indirect (inline)
         0     0%   100%      0.02s  1.09%  reflect.Value.Interface (inline)
         0     0%   100%      0.02s  1.09%  reflect.packEface
         0     0%   100%      0.01s  0.55%  reflect.unsafe_New
         0     0%   100%      0.02s  1.09%  reflect.valueInterface
         0     0%   100%      0.01s  0.55%  runtime.(*hmap).newoverflow
         0     0%   100%      0.13s  7.10%  runtime.(*mcache).nextFree
         0     0%   100%      0.12s  6.56%  runtime.(*mcache).refill
         0     0%   100%      0.11s  6.01%  runtime.(*mcentral).grow
         0     0%   100%      0.11s  6.01%  runtime.(*mheap).alloc
         0     0%   100%      0.03s  1.64%  runtime.(*mheap).alloc.func1
         0     0%   100%      0.03s  1.64%  runtime.(*mheap).allocSpan
         0     0%   100%      0.01s  0.55%  runtime.(*pageAlloc).allocToCache
         0     0%   100%      0.01s  0.55%  runtime.(*pageAlloc).find
         0     0%   100%      0.01s  0.55%  runtime.(*pallocBits).find
         0     0%   100%      0.03s  1.64%  runtime.Caller
         0     0%   100%      0.02s  1.09%  runtime.acquirep
         0     0%   100%      0.03s  1.64%  runtime.assertE2I2
         0     0%   100%      0.02s  1.09%  runtime.callers
         0     0%   100%      0.02s  1.09%  runtime.callers.func1
         0     0%   100%      0.01s  0.55%  runtime.concatstring3
         0     0%   100%      0.01s  0.55%  runtime.concatstrings
         0     0%   100%      0.01s  0.55%  runtime.convTstring
         0     0%   100%      0.08s  4.37%  runtime.copystack
         0     0%   100%      0.01s  0.55%  runtime.entersyscall
         0     0%   100%      0.01s  0.55%  runtime.entersyscall_sysmon
         0     0%   100%      0.02s  1.09%  runtime.exitsyscall
         0     0%   100%      0.01s  0.55%  runtime.exitsyscallfast
         0     0%   100%      0.22s 12.02%  runtime.findrunnable
         0     0%   100%      0.02s  1.09%  runtime.funcspdelta
         0     0%   100%      0.03s  1.64%  runtime.futexsleep
         0     0%   100%      0.07s  3.83%  runtime.futexwakeup
         0     0%   100%      0.03s  1.64%  runtime.getitab
         0     0%   100%      0.01s  0.55%  runtime.gfget
         0     0%   100%      0.01s  0.55%  runtime.gfget.func1
         0     0%   100%      0.10s  5.46%  runtime.goexit0
         0     0%   100%      0.02s  1.09%  runtime.goready
         0     0%   100%      0.02s  1.09%  runtime.goready.func1
         0     0%   100%      0.01s  0.55%  runtime.heapBitsSetType
         0     0%   100%      0.03s  1.64%  runtime.mPark
         0     0%   100%      0.13s  7.10%  runtime.makeslice
         0     0%   100%      0.21s 11.48%  runtime.mallocgc
         0     0%   100%      0.01s  0.55%  runtime.mapassign
         0     0%   100%      0.26s 14.21%  runtime.mcall
         0     0%   100%      0.02s  1.09%  runtime.memclrNoHeapPointersChunked
         0     0%   100%      0.06s  3.28%  runtime.newproc
         0     0%   100%      0.02s  1.09%  runtime.newproc1
         0     0%   100%      0.03s  1.64%  runtime.notesleep
         0     0%   100%      0.07s  3.83%  runtime.notewakeup
         0     0%   100%      0.16s  8.74%  runtime.park_m
         0     0%   100%      0.01s  0.55%  runtime.rawstring
         0     0%   100%      0.01s  0.55%  runtime.rawstringtmp
         0     0%   100%      0.02s  1.09%  runtime.ready
         0     0%   100%      0.02s  1.09%  runtime.readyWithTime
         0     0%   100%      0.01s  0.55%  runtime.reentersyscall
         0     0%   100%      0.03s  1.64%  runtime.resetspinning
         0     0%   100%      0.02s  1.09%  runtime.runqsteal
         0     0%   100%      0.25s 13.66%  runtime.schedule
         0     0%   100%      0.01s  0.55%  runtime.semrelease1
         0     0%   100%      0.03s  1.64%  runtime.slicebytetostring
         0     0%   100%      0.07s  3.83%  runtime.startm
         0     0%   100%      0.03s  1.64%  runtime.stopm
         0     0%   100%      0.14s  7.65%  runtime.systemstack
         0     0%   100%      0.01s  0.55%  runtime.typedmemmove
         0     0%   100%      0.01s  0.55%  runtime.typedslicecopy
         0     0%   100%      0.07s  3.83%  runtime.wakep
         0     0%   100%      0.01s  0.55%  strconv.AppendQuote (inline)
         0     0%   100%      0.01s  0.55%  sync.(*Cond).Signal
         0     0%   100%      0.01s  0.55%  sync.(*Mutex).unlockSlow
         0     0%   100%      0.07s  3.83%  sync.(*Pool).Get
         0     0%   100%      0.01s  0.55%  sync.(*Pool).Put
         0     0%   100%      0.01s  0.55%  sync.(*Pool).getSlow
         0     0%   100%      0.01s  0.55%  sync.(*poolChain).popTail
         0     0%   100%      0.01s  0.55%  sync.runtime_Semrelease
         0     0%   100%      0.01s  0.55%  sync.runtime_notifyListNotifyOne
         0     0%   100%      0.32s 17.49%  syscall.Read (inline)
         0     0%   100%      0.01s  0.55%  syscall.Stat (inline)
         0     0%   100%      0.18s  9.84%  syscall.Write (inline)
         0     0%   100%      0.01s  0.55%  syscall.fstatat
         0     0%   100%      0.32s 17.49%  syscall.read
         0     0%   100%      0.18s  9.84%  syscall.write
         0     0%   100%      0.01s  0.55%  time.Time.Date (inline)
         0     0%   100%      0.01s  0.55%  time.Time.date
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*Decoder).Write
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*Decoder).parseFieldLiteral
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*Decoder).parseHeaderFieldRepr
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*Decoder).readString
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*Encoder).WriteField
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*dynamicTable).add
         0     0%   100%      0.01s  0.55%  vendor/golang.org/x/net/http2/hpack.(*headerFieldTable).addEntry (inline)

ncw · June 27, 2022, 3:28pm

THis doesn't look like rclone is using a lot of CPU in itself, only 1.83/30 so approx 6% of your CPU.

I suspect what is happening it is the applications waiting for the mount that are contributing to the load average that is the problem rather than rclone itself.

If you run vmstat 5 and let it run for a minute while busy

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0 942552 3258032 2457568 28051068    0    1   253   121   13   16  7  5 88  0  0
 0  0 942552 3291720 2457604 28045948    0    0     0    66 5307 11799  1  1 98  0  0
 0  0 942552 3285512 2457636 28049388    0    0     2   713 2343 3611  1  0 99  0  0

My prediction is that you are going to see a large number in the b column for processes waiting on IO.

To fix that you will need to fix the timeouts that rclone is seeing I think.

cberni · June 27, 2022, 3:44pm

yes. Is not much use. In the case is just a simple rclone mount.

witch timeouts do you mean?
I already set --low-level-retries 1 --contimeout 30s --timeout 60s

in -vv log messages below when the problem happens... just restart de mount and than stop the messasges in log and the load average goes back to normal.

2022/06/27 10:13:32 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0C8?generation=1641316005117386&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:32 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A5?generation=1641278789252361&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:32 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F5%2F5%2F15%2F8F024F34%2FCA92BD0F%2F8F9D30AB?generation=1627098650690068&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:32 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A9?generation=1641278791305487&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:32 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0CF?generation=1641316011258466&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C1?generation=1641278792703224&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDE2?generation=1641280352313019&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDFD?generation=1641280355076798&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0EA?generation=1641316017036002&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C5?generation=1641278794464357&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FE03?generation=1641280357482727&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:13:33 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700AA?generation=1641280360276086&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:32 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0C8?generation=1641316005117386&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:32 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C0C8 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0C8?generation=1641316005117386&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:32 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A5?generation=1641278789252361&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:32 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5A5 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A5?generation=1641278789252361&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:32 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F5%2F5%2F15%2F8F024F34%2FCA92BD0F%2F8F9D30AB?generation=1627098650690068&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:32 DEBUG : &{pacs-data/archive/2021/5/5/15/8F024F34/CA92BD0F/8F9D30AB (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F5%2F5%2F15%2F8F024F34%2FCA92BD0F%2F8F9D30AB?generation=1627098650690068&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:32 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A9?generation=1641278791305487&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:32 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5A9 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A9?generation=1641278791305487&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:32 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0CF?generation=1641316011258466&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:32 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C0CF (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0CF?generation=1641316011258466&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:33 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C1?generation=1641278792703224&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:33 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5C1 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C1?generation=1641278792703224&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:33 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDE2?generation=1641280352313019&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:33 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/5516FDE2 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDE2?generation=1641280352313019&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:35 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDFD?generation=1641280355076798&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:35 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/5516FDFD (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDFD?generation=1641280355076798&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:37 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0EA?generation=1641316017036002&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:37 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C0EA (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0EA?generation=1641316017036002&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:39 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C5?generation=1641278794464357&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:39 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5C5 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C5?generation=1641278794464357&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:41 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FE03?generation=1641280357482727&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:41 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/5516FE03 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FE03?generation=1641280357482727&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:43 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700AA?generation=1641280360276086&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:14:43 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/551700AA (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700AA?generation=1641280360276086&alt=media": http2: timeout awaiting response headers
2022/06/27 10:14:45 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/storage/v1/b/bucket_name/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2018%2F6%2F14%2F14%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/06/27 10:15:32 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C105?generation=1641316022539136&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:34 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0C8?generation=1641316005117386&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:36 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C10B?generation=1641316027716377&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:38 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A5?generation=1641278789252361&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:40 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F5%2F5%2F15%2F8F024F34%2FCA92BD0F%2F8F9D30AB?generation=1627098650690068&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:42 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E0?generation=1641278797530123&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:44 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A9?generation=1641278791305487&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:46 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C8?generation=1641278795805171&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:48 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C127?generation=1641316033419586&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:50 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0CF?generation=1641316011258466&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:52 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C1?generation=1641278792703224&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:54 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E3?generation=1641278798921556&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:56 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDE2?generation=1641280352313019&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:15:58 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700C5?generation=1641280362663057&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:00 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700CB?generation=1641280365129727&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:02 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDFD?generation=1641280355076798&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:04 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C142?generation=1641316038946717&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:06 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0EA?generation=1641316017036002&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:08 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E7?generation=1641278801029234&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:10 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C5?generation=1641278794464357&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:12 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700E6?generation=1641280367556565&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:14 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FE03?generation=1641280357482727&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:16 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700AA?generation=1641280360276086&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:18 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700ED?generation=1641280370440919&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:20 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/storage/v1/b/bucket_name/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2018%2F6%2F14%2F14%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/06/27 10:16:20 ERROR : pacs-data/archive/2018/6/14/14/: Dir.Stat error: Get "https://storage.googleapis.com/storage/v1/b/bucket_name/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2018%2F6%2F14%2F14%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/06/27 10:16:20 DEBUG : pacs-data/archive/2018/6/14/14/: >Lookup: node=<nil>, err=Get "https://storage.googleapis.com/storage/v1/b/bucket_name/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2018%2F6%2F14%2F14%2F&prettyPrint=false": http2: timeout awaiting response headers
2022/06/27 10:16:22 DEBUG : pacer: low level retry 1/2 (error Get "https://storage.googleapis.com/storage/v1/b/bucket_name/o?alt=json&delimiter=%2F&maxResults=1000&prefix=pacs-data%2Farchive%2F2020%2F12%2F14%2F16%2F6BE56BD0%2F&prettyPrint=false": http2: timeout awaiting response headers)
2022/06/27 10:16:32 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C105?generation=1641316022539136&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:32 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C105 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C105?generation=1641316022539136&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:34 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0C8?generation=1641316005117386&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:34 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C0C8 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0C8?generation=1641316005117386&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:36 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C10B?generation=1641316027716377&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:36 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C10B (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C10B?generation=1641316027716377&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:38 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A5?generation=1641278789252361&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:38 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5A5 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A5?generation=1641278789252361&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:40 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F5%2F5%2F15%2F8F024F34%2FCA92BD0F%2F8F9D30AB?generation=1627098650690068&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:40 DEBUG : &{pacs-data/archive/2021/5/5/15/8F024F34/CA92BD0F/8F9D30AB (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F5%2F5%2F15%2F8F024F34%2FCA92BD0F%2F8F9D30AB?generation=1627098650690068&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:42 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E0?generation=1641278797530123&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:42 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5E0 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E0?generation=1641278797530123&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:44 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A9?generation=1641278791305487&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:44 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5A9 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5A9?generation=1641278791305487&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:46 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C8?generation=1641278795805171&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:46 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5C8 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C8?generation=1641278795805171&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:48 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C127?generation=1641316033419586&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:48 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C127 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C127?generation=1641316033419586&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:50 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0CF?generation=1641316011258466&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:50 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C0CF (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0CF?generation=1641316011258466&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:52 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C1?generation=1641278792703224&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:52 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5C1 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5C1?generation=1641278792703224&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:54 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E3?generation=1641278798921556&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:54 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40C/5508E5E3 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40C%2F5508E5E3?generation=1641278798921556&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:56 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDE2?generation=1641280352313019&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:56 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/5516FDE2 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDE2?generation=1641280352313019&alt=media": http2: timeout awaiting response headers
2022/06/27 10:16:58 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700C5?generation=1641280362663057&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:16:58 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/551700C5 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700C5?generation=1641280362663057&alt=media": http2: timeout awaiting response headers
2022/06/27 10:17:00 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700CB?generation=1641280365129727&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:17:00 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/551700CB (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F551700CB?generation=1641280365129727&alt=media": http2: timeout awaiting response headers
2022/06/27 10:17:02 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDFD?generation=1641280355076798&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:17:02 DEBUG : &{pacs-data/archive/2021/11/3/10/244B83E0/3F96C40D/5516FDFD (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F10%2F244B83E0%2F3F96C40D%2F5516FDFD?generation=1641280355076798&alt=media": http2: timeout awaiting response headers
2022/06/27 10:17:04 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C142?generation=1641316038946717&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:17:04 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C142 (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C142?generation=1641316038946717&alt=media": http2: timeout awaiting response headers
2022/06/27 10:17:06 DEBUG : pacer: low level retry 2/2 (error Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0EA?generation=1641316017036002&alt=media": http2: timeout awaiting response headers)
2022/06/27 10:17:06 DEBUG : &{pacs-data/archive/2021/11/3/9/244B83E0/3F7A7AC1/B4D9C0EA (r)}: >Read: read=0, err=Get "https://storage.googleapis.com/download/storage/v1/b/bucket_name/o/pacs-data%2Farchive%2F2021%2F11%2F3%2F9%2F244B83E0%2F3F7A7AC1%2FB4D9C0EA?generation=1641316017036002&alt=media": http2: timeout awaiting response headers

ncw · June 27, 2022, 6:53pm

Does the mount ever get working again with those settings once the connectivity is back?

If we made an easy way to restart the mount would that make your life easier?

I suspect for your use what we need to do is detect the connectivity going down and up and restart the mount each time. If we could do a soft restart of the mount from within rclone then that would make things very neat.

Every time you restart the mount, the applications waiting on files will potentially give errors though.

cberni · June 27, 2022, 7:46pm

in this case, don't have lost connectivity. no network problens. The internet is working fine and it keep having some timeouts.

I suspect that some sort of instability happens and it can no longer get the files on a second try. Could it be an authentication error on the second attempt?