Throttling of rclone with Sharepoint - saga continues

Help and Support
1

What is the problem you are having with rclone?

rclone is throttled by Microsoft Sharepoint during copy/sync commands, eventually stalling altogether.

This problem and the general topic is not unlike that identified in this thread or many of those here. I am just hoping to continue the discussion and register another example.

In the case the file archive consists of about 10,000 files, with maybe 50 directories, and a total size of just under 100 GB.

I initially uploaded the entire archive by "drag-and-drop" directly into Sharepoint via a web browser interface. The entire transfer completed very quickly (< 30 min) with transfer rates of several 10's of MB/s. However Sharepoint registered that 11 files failed to upload, frustratingly without identifying which 11 files. So my hope was to use rclone to identify and re-transfer the 11 files and in general going forward for these kinds of transfers.

I have read Microsoft's description of their throttling and many of the other threads on this forum, and generally understand the problem. I have a few observations:

  1. Folks have observed that Microsoft is distinguishing Sharepoint from Azure storage by more severely throttling Sharepoint/Onedrive and providing them at different price points. If that's the case, then Sharepoint is probably not a good solution for those like myself with large data sets and the need for tools like rclone to manage them.
  2. It is interesting to note, that my initial upload through the Sharepoint browser interface did not get throttled in any way. This makes me wonder if throttling is either not applied to Microsoft's own interfaces, or if the rclone algorithm could be made to mimic Sharepoint's methods.

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

rclone -V
rclone v1.57.0

  • os/version: darwin 12.1 (64 bit)
  • os/kernel: 21.2.0 (x86_64)
  • os/type: darwin
  • os/arch: amd64
  • go/version: go1.17.2
  • go/linking: dynamic
  • go/tags: none

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

Sharepoint

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

Throttling occurs with/without --tpslimit, or with tsp limit set as low as 3.

rclone copy -P --tpslimit=10 --log-level DEBUG --log-file=rclonelog.txt /Volumes/ASV_03/DRIX/NA136/DX082201 oeci_data:DRIX08/drix_data/DX082201

The rclone config contents with secrets removed.

[oeci_data]
type = onedrive
token = {"access_token":""
expiry":"2022-03-22T19:01:20.12712-04:00"}
drive_id = ""
drive_type = documentLibrary

A log from the command with the -vv flag

This is a representative example in which the process was stopped after it was clear it would throttle and eventually stall altogether.

2022/03/22 15:39:51 INFO  : Starting transaction limiter: max 10 transactions/s with burst 1
2022/03/22 15:39:51 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "copy" "-P" "--tpslimit=10" "--log-level" "DEBUG" "--log-file=rclonelog.txt" "/Volumes/ASV_03/DRIX/NA136/DX082201" "oeci_data:DRIX08/drix_data/DX082201"]
2022/03/22 15:39:51 DEBUG : Creating backend with remote "/Volumes/ASV_03/DRIX/NA136/DX082201"
2022/03/22 15:39:51 DEBUG : Using config file from "/Users/vschmidt/.config/rclone/rclone.conf"
2022/03/22 15:39:51 DEBUG : Creating backend with remote "oeci_data:DRIX08/drix_data/DX082201"
2022/03/22 15:39:54 DEBUG : ._.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:54 DEBUG : ._.DS_Store: Unchanged skipping
2022/03/22 15:39:54 DEBUG : .DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:54 DEBUG : manifest.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:54 DEBUG : manifest.txt: Unchanged skipping
2022/03/22 15:39:54 DEBUG : ._ExpeditionDescription.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:54 DEBUG : ._ExpeditionDescription.json: Unchanged skipping
2022/03/22 15:39:54 DEBUG : .DS_Store: Unchanged skipping
2022/03/22 15:39:54 DEBUG : ExpeditionDescription.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:54 DEBUG : ExpeditionDescription.json: Unchanged skipping
2022/03/22 15:39:54 DEBUG : manifest_temp.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:54 DEBUG : manifest_temp.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/._.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/._.DS_Store: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/._2022_NautilusShakedownLogFINAL.docx: Size and modification time the same (differ by -90ms, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/._2022_NautilusShakedownLogFINAL.docx: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/.DS_Store: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/2022_NautilusShakedownLog_2022-03-05.docx: Starting multipart upload
2022/03/22 15:39:55 DEBUG : drix08/2022_NautilusShakedownLog_2022-03-08.docx: Starting multipart upload
2022/03/22 15:39:55 DEBUG : drix08/2022_NautilusShakedownLogFINAL.docx: Starting multipart upload
2022/03/22 15:39:55 DEBUG : .data_manager/._.DS_Store.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : .data_manager/manifest_temp.txt.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : .data_manager/manifest_temp.txt.json: Unchanged skipping
2022/03/22 15:39:55 DEBUG : .data_manager/.DS_Store.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : .data_manager/.DS_Store.json: Unchanged skipping
2022/03/22 15:39:55 DEBUG : .data_manager/ExpeditionDescription.json.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : .data_manager/ExpeditionDescription.json.json: Unchanged skipping
2022/03/22 15:39:55 DEBUG : .data_manager/._.DS_Store.json: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/._00-driX08_metadatasummary.csv: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/._00-driX08_metadatasummary.csv: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/._.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/._.DS_Store: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/._00-driX08_metadatasummary.xls: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/._00-driX08_metadatasummary.xls: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/00-driX08_metadatasummary.csv: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/00-driX08_metadatasummary.csv: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/.DS_Store: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/00-driX08_metadatasummary.xls: Sizes differ (src 31232 vs dst 36352)
2022/03/22 15:39:55 DEBUG : drix08/05-metadata/00-driX08_metadatasummary.xls: Starting multipart upload
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/DataCatalog.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_02.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_02.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_01.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_01.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_01.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_01.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_05.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/DataCatalog.json: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_06.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_03.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_03.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_06.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_03.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_03.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_07.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_07.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_02.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_02.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployments.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployments.json: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_04.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_04.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_04.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_04.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_05.nav.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_05.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_05.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_06.nav.txt: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_06.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_07.nav.txt.kml: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/deployment_07.nav.txt.kml: Unchanged skipping
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/ExpeditionManifest.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:55 DEBUG : drix08/01-catalog/ExpeditionManifest.txt: Unchanged skipping
2022/03/22 15:39:56 DEBUG : Too many requests. Trying again in 318 seconds.
2022/03/22 15:39:56 DEBUG : pacer: low level retry 1/10 (error activityLimitReached: throttledRequest: The request has been throttled)
2022/03/22 15:39:56 DEBUG : pacer: Rate limited, increasing sleep to 5m18s
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 3m58.5s
2022/03/22 15:39:56 DEBUG : drix08/2022_NautilusShakedownLog_2022-03-05.docx: Uploading segment 0/408726 size 408726
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 2m58.875s
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/._.DS_Store.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/._.DS_Store.json: Unchanged skipping
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/2022_NautilusShakedownLogFINAL.docx.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/2022_NautilusShakedownLogFINAL.docx.json: Unchanged skipping
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/.DS_Store.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/.DS_Store.json: Unchanged skipping
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/2022_NautilusShakedownLog_2022-03-05.docx.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/2022_NautilusShakedownLog_2022-03-05.docx.json: Unchanged skipping
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/2022_NautilusShakedownLog_2022-03-08.docx.json: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : .data_manager/drix08/2022_NautilusShakedownLog_2022-03-08.docx.json: Unchanged skipping
2022/03/22 15:39:56 DEBUG : Too many requests. Trying again in 58 seconds.
2022/03/22 15:39:56 DEBUG : pacer: low level retry 1/10 (error activityLimitReached: throttledRequest: The request has been throttled)
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 2m14.15625s
2022/03/22 15:39:56 DEBUG : drix08/2022_NautilusShakedownLog_2022-03-08.docx: Uploading segment 0/4408729 size 4408729
2022/03/22 15:39:56 DEBUG : pacer: Rate limited, increasing sleep to 58s
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 43.5s
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/drix/._.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/drix/._.DS_Store: Unchanged skipping
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/drix/.DS_Store: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/drix/.DS_Store: Unchanged skipping
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 32.625s
2022/03/22 15:39:56 DEBUG : drix08/2022_NautilusShakedownLogFINAL.docx: Uploading segment 0/5585452 size 5585452
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 24.46875s
2022/03/22 15:39:56 ERROR : drix08/05-metadata/00-driX08_metadatasummary.xls: Failed to copy: nameAlreadyExists: A file with the same name is currently being uploaded. Change the filename and try to save again. (is it a OneNote file?)
2022/03/22 15:39:56 DEBUG : pacer: Reducing sleep to 18.3515625s
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/gps/DRIX_AsteRx-U-Fg_3234554_diagnosticreport_2022-03-08-182638.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/gps/DRIX_AsteRx-U-Fg_3234554_diagnosticreport_2022-03-08-182638.txt: Unchanged skipping
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/gps/drix_marinestar.png: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/gps/drix_marinestar.png: Unchanged skipping
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/gps/UDS_AsteRx-U_3234599_diagnosticreport_2022-03-08-182501.txt: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:56 DEBUG : drix08/05-metadata/gps/UDS_AsteRx-U_3234599_diagnosticreport_2022-03-08-182501.txt: Unchanged skipping
2022/03/22 15:39:57 DEBUG : pacer: Reducing sleep to 13.763671875s
2022/03/22 15:39:57 DEBUG : drix08/05-metadata/mbes/443810ad_em2040_mkii_data_sheet.pdf: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:57 DEBUG : drix08/05-metadata/mbes/SIS5_version_20220301.JPG: Size and modification time the same (differ by 0s, within tolerance 1s)
2022/03/22 15:39:57 DEBUG : drix08/05-metadata/mbes/SIS5_version_20220301.JPG: Unchanged skipping
2022/03/22 15:39:57 DEBUG : drix08/05-metadata/mbes/443810ad_em2040_mkii_data_sheet.pdf: Unchanged skipping
2022/03/22 15:39:57 DEBUG : Too many requests. Trying again in 38 seconds.
2022/03/22 15:39:57 DEBUG : pacer: low level retry 1/10 (error activityLimitReached: throttledRequest: The request has been throttled)
2022/03/22 15:39:57 DEBUG : pacer: Rate limited, increasing sleep to 38s
2022/03/22 15:39:57 DEBUG : Too many requests. Trying again in 32 seconds.
2022/03/22 15:39:57 DEBUG : pacer: low level retry 2/10 (error activityLimitReached: throttledRequest: The request has been throttled)
2022/03/22 15:39:57 DEBUG : pacer: Rate limited, increasing sleep to 32s
2022/03/22 15:39:57 DEBUG : pacer: Reducing sleep to 24s
2022/03/22 15:40:10 INFO  : Signal received: interrupt
2022/03/22 15:40:10 DEBUG : drix08/2022_NautilusShakedownLog_2022-03-08.docx: Cancelling multipart upload: <nil>
2022/03/22 15:40:19 INFO  : Starting transaction limiter: max 5 transactions/s with burst 1
2022/03/22 15:40:19 DEBUG : rclone: Version "v1.57.0" starting with parameters ["rclone" "copy" "-P" "--tpslimit=5" "--log-level" "DEBUG" "--log-file=rclonelog.txt" "/Volumes/ASV_03/DRIX/NA136/DX082201" "oeci_data:DRIX08/drix_data/DX082201"]
2022/03/22 15:40:19 DEBUG : Creating backend with remote "/Volumes/ASV_03/DRIX/NA136/DX082201"
2022/03/22 15:40:19 DEBUG : Using config file from "/Users/vschmidt/.config/rclone/rclone.conf"
2022/03/22 15:40:19 DEBUG : Creating backend with remote "oeci_data:DRIX08/drix_data/DX082201"
2022/03/22 15:40:20 DEBUG : Too many requests. Trying again in 327 seconds.
2022/03/22 15:40:20 DEBUG : pacer: low level retry 1/10 (error activityLimitReached: throttledRequest: The request has been throttled)
2022/03/22 15:40:20 DEBUG : pacer: Rate limited, increasing sleep to 5m27s
2022/03/22 15:40:20 DEBUG : Too many requests. Trying again in 304 seconds.
2022/03/22 15:40:20 DEBUG : pacer: low level retry 2/10 (error activityLimitReached: throttledRequest: The request has been throttled)
2022/03/22 15:40:20 DEBUG : pacer: Rate limited, increasing sleep to 5m4s
2

I opened the thread you linked. The workaround I found was to use --checkers 1, as pointed in this reply. Have you tried it? After applying that switch, I never noticed throttling anymore. Of course it leads to big decrease in performance, but I doubt this problem will ever be truly solved until adaptive threading reduction is implemented.

1 Like
3

I fully agree with a single addition:

The transfer speed would still be similar in situations like yours, it would just remove the manual troubleshooting, research, and frustration to reach --checkers=1.

An automatic adjustment would however need to be performed each time a copy/sync is started, so there will still be some throttling initially and each time the pacer checks to see if --checkers can be increased again. A fixed --checkers=1 will therefore give the best results, but it unfortunately requires some upfront reading and testing.

Perhaps we should add an extra section in the docs where we pass a hint to reduce --checkers (and --transfers) in case of excessive SharePoint throttling - something like this. Would such a section save time and troubles?

I wonder why we sometimes see this kind of issues with SharePoint. I see far better speeds on my OneDrive Personal Premium with more files, folders, and data. I also have an impression that these issues don't affect everybody with SharePoint. Could it be a limitation on the lowest priced business plans, certain regions or something similar?

4

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