MonkeyNinja
commented
1 year ago any progress on this? 10 minutes for 14 files????!!
0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed)
.... many more rows....
0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 0.0 %, 0 Done, 0 Failed, 14 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 15.0 %, 3 Done, 0 Failed, 11 Pending, 14 Total, 2-sec Throughput (Mb/s): 0.581 (Disk may be limiting speed) 54.4 %, 5 Done, 0 Failed, 9 Pending, 14 Total, 2-sec Throughput (Mb/s): 1.5229 (Disk may be limiting speed) 79.3 %, 8 Done, 0 Failed, 6 Pending, 14 Total, 2-sec Throughput (Mb/s): 0.9629 (Disk may be limiting speed) 79.3 %, 8 Done, 0 Failed, 6 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 94.6 %, 11 Done, 0 Failed, 3 Pending, 14 Total, 2-sec Throughput (Mb/s): 0.5934 (Disk may be limiting speed) 96.6 %, 13 Done, 0 Failed, 1 Pending, 14 Total, 2-sec Throughput (Mb/s): 0.0766 (Disk may be limiting speed) 96.6 %, 13 Done, 0 Failed, 1 Pending, 14 Total, 2-sec Throughput (Mb/s): 0 (Disk may be limiting speed) 100.0 %, 14 Done, 0 Failed, 0 Pending, 14 Total, 2-sec Throughput (Mb/s): 0.132
Job f19e901e-382c-2442-7fde-3937742cd754 Summary Files Scanned at Source: 1373 Files Scanned at Destination: 1377 Elapsed Time (Minutes): 9.7702 Number of Copy Transfers for Files: 12 Number of Copy Transfers for Folder Properties: 2 Total Number Of Copy Transfers: 14 Number of Copy Transfers Completed: 14 Number of Copy Transfers Failed: 0 Number of Deletions at Destination: 116 Total Number of Bytes Transferred: 967484 Total Number of Bytes Enumerated: 967484 Final Job Status: Completed
Which version of the AzCopy was used?
10.16.2
Which platform are you using? (ex: Windows, Mac, Linux)
linux
What command did you run?
What problem was encountered?
azcopy sync used to be blazingly fast....now it seems to really struggle
network tests seems ok
ethtool reports linke speed of 10000 mb/s
How can we reproduce the problem in the simplest way?
attempt so sync around a 1000 files in folders to azure file storage repeat sync
Have you found a mitigation/solution?
no
azcopy sync ouput, 8 minutes to sync 1,000 files????
100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 100.0 %, 1 Done, 0 Failed, 0 Pending, 1 Total, 2-sec Throughput (Mb/s): 0
Job a1291151-3187-1b49-550f-8e319bcce5f4 Summary Files Scanned at Source: 1316 Files Scanned at Destination: 1316 Elapsed Time (Minutes): 8.0031 Number of Copy Transfers for Files: 0 Number of Copy Transfers for Folder Properties: 1 Total Number Of Copy Transfers: 1 Number of Copy Transfers Completed: 1 Number of Copy Transfers Failed: 0 Number of Deletions at Destination: 1 Total Number of Bytes Transferred: 0 Total Number of Bytes Enumerated: 0 Final Job Status: Completed
"timestamp":"2023-01-06T12:42:38.756Z","msg":"2023/01/06 12:34:38 AzcopyVersion 10.16.2 2023/01/06 12:34:38 OS-Environment linux 2023/01/06 12:34:38 OS-Architecture amd64 2023/01/06 12:34:38 Log times are in UTC. Local time is 6 Jan 2023 12:34:38 2023/01/06 12:34:38 ISO 8601 START TIME: to copy files that changed before or after this job started, use the parameter --include-before=2023-01-06T12:34:33Z or --include-after=2023-01-06T12:34:33Z 2023/01/06 12:34:38 Any empty folders will be processed, because source and destination both support folders 2023/01/06 12:34:45 Job-Command sync fpgs-files https://REDACTED.file.core.windows.net/gs-fp-files?se=2023-01-06t13%3A34%3A38z&sig=-REDACTED-&sp=rwdlacup&spr=https&srt=sco&ss=f&st=2023-01-06t12%3A34%3A38z&sv=2020-10-02 --delete-destination=true 2023/01/06 12:34:45 Number of CPUs: 8 2023/01/06 12:34:45 Max file buffer RAM 4.000 GB 2023/01/06 12:34:45 Max concurrent network operations: 128 (Based on number of CPUs. Set AZCOPY_CONCURRENCY_VALUE environment variable to override) 2023/01/06 12:34:45 Check CPU usage when dynamically tuning concurrency: true (Based on hard-coded default. Set AZCOPY_TUNE_TO_CPU environment variable to true or false override) 2023/01/06 12:34:45 Max concurrent transfer initiation routines: 64 (Based on hard-coded default. Set AZCOPY_CONCURRENT_FILES environment variable to override) 2023/01/06 12:34:45 Max enumeration routines: 16 (Based on hard-coded default. Set AZCOPY_CONCURRENT_SCAN environment variable to override) 2023/01/06 12:34:45 Parallelize getting file properties (file.Stat): false (Based on AZCOPY_PARALLEL_STAT_FILES environment variable) 2023/01/06 12:34:45 Max open files when downloading: 1048047 (auto-computed) 2023/01/06 12:34:45 Final job part has been created 2023/01/06 12:34:45 scheduling JobID=a1291151-3187-1b49-550f-8e319bcce5f4, Part#=0, Transfer#=0, priority=0 2023/01/06 12:34:45 Final job part has been scheduled 2023/01/06 12:34:45 INFO: [P#0-T#0] has worker 32 which is processing TRANSFER 0 2023/01/06 12:34:45 WARN: [P#0-T#0] Block size 8388608 larger than maximum file chunk size, 4 MB chunk size used 2023/01/06 12:34:46 PERF: primary performance constraint is Unknown. States: X: 0, O:
many more log lines including i/o timeouts
2023/01/06 12:35:14 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 2023/01/06 12:35:15 ==> REQUEST/RESPONSE (Try=1/30.001017573s[SLOW >3s], OpTime=30.001079379s) -- REQUEST ERROR GET https://REDACTED.file.core.windows.net/gs-fp-files/bmds-data?restype=directory&se=2023-01-06T13%3A34%3A38Z&sig=-REDACTED-&sp=rwdlacup&spr=https&srt=sco&ss=f&st=2023-01-06T12%3A34%3A38Z&sv=2020-10-02&timeout=901 User-Agent: [AzCopy/10.16.2 Azure-Storage/0.8.0 (go1.17.9; linux)] X-Ms-Client-Request-Id: [1981a2e3-930a-4662-5938-5f4596493fff] X-Ms-Version: [2020-10-02]
ERROR: -> github.com/Azure/azure-pipeline-go/pipeline.NewError, /home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/error.go:157 HTTP request failed
Get "https://REDACTED.file.core.windows.net/gs-fp-files/bmds-data?restype=directory&se=2023-01-06T13%3A34%3A38Z&sig=-REDACTED-&sp=rwdlacup&spr=https&srt=sco&ss=f&st=2023-01-06T12%3A34%3A38Z&sv=2020-10-02&timeout=901": dial tcp 20.60.166.168:443: i/o timeout
goroutine 2112 [running]: github.com/Azure/azure-storage-azcopy/v10/ste.stack() \t/home/vsts/work/1/s/ste/xferLogPolicy.go:237 +0x65 github.com/Azure/azure-storage-azcopy/v10/ste.NewRequestLogPolicyFactory.func1.1({0x1017720, 0xc000238180}, {0xc0007c16d0}) \t/home/vsts/work/1/s/ste/xferLogPolicy.go:151 +0xa29 github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xddf5a0, {0x1017720, 0xc000238180}, {0xc}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:43 +0x2f github.com/Azure/azure-storage-azcopy/v10/ste.NewVersionPolicyFactory.func1.1({0x1017720, 0xc000238180}, {0xc000100000}) \t/home/vsts/work/1/s/ste/mgr-JobPartMgr.go:88 +0x157 github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc0007c1738, {0x1017720, 0xc000238180}, {0xc0007c1738}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:43 +0x2f github.com/Azure/azure-storage-file-go/azfile.responderPolicy.Do({{0x10029c0, 0xc000696648}, 0xc0013360b0}, {0x1017720, 0xc000238180}, {0xc00058c800}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/zz_generated_responder_policy.go:33 +0x44 github.com/Azure/azure-storage-file-go/azfile.anonymousCredentialPolicy.Do(...) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/zc_credential_anonymous.go:54 github.com/Azure/azure-storage-azcopy/v10/ste.(retryNotificationPolicy).Do(0xc0007c17c8, {0x1017720, 0xc000238180}, {0x10176b0}) \t/home/vsts/work/1/s/ste/xferRetryNotificationPolicy.go:59 +0x2f github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0x10176b0, {0x1017720, 0xc000238180}, {0x7}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:43 +0x2f github.com/Azure/azure-storage-file-go/azfile.NewRetryPolicyFactory.func1.1({0x10176b0, 0xc00128d580}, {0xc0007c1aa8}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/zc_policy_retry.go:194 +0x877 github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xddf5a0, {0x10176b0, 0xc00128d580}, {0x16}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:43 +0x2f github.com/Azure/azure-storage-file-go/azfile.NewUniqueRequestIDPolicyFactory.func1.1({0x10176b0, 0xc00128d580}, {0xc0007c1b48}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/zc_policy_unique_request_id.go:19 +0x163 github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xddf5a0, {0x10176b0, 0xc00128d580}, {0xa}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:43 +0x2f github.com/Azure/azure-storage-file-go/azfile.NewTelemetryPolicyFactory.func1.1({0x10176b0, 0xc00128d580}, {0xc000010338}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/zc_policy_telemetry.go:34 +0x11c github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc00128d540, {0x10176b0, 0xc00128d580}, {0x415365}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:43 +0x2f github.com/Azure/azure-pipeline-go/pipeline.(pipeline).Do(0xe61480, {0x10176b0, 0xc00128d580}, {0x1002b80, 0xc0013360b0}, {0xc0018c4008}) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-pipeline-go@v0.2.4-0.20220425205405-09e6f201e1e4/pipeline/core.go:129 +0x54 github.com/Azure/azure-storage-file-go/azfile.directoryClient.GetProperties({{{{0xc0018c4000, 0x5}, {0x0, 0x0}, 0x0, {0xc0018c4008, 0x21}, {0xc0018c4029, 0x16}, {0x0, ...}, ...}, ...}}, ...) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/zz_generated_directory.go:234 +0x2db github.com/Azure/azure-storage-file-go/azfile.DirectoryURL.GetProperties(...) \t/home/vsts/go/pkg/mod/github.com/!azure/azure-storage-file-go@v0.6.1-0.20201111053559-3c1754dc00a5/azfile/url_directory.go:83 github.com/Azure/azure-storage-azcopy/v10/ste.AzureFileParentDirCreator.CreateDirToRoot({}, {0x10176b0, 0xc00128d580}, {{{{{...}, {...}, 0x0, {...}, {...}, {...}, 0x0, ...}, ...}}}, ...) \t/home/vsts/work/1/s/ste/sender-azureFile.go:454 +0x194 github.com/Azure/azure-storage-azcopy/v10/ste.(azureFileSenderBase).EnsureFolderExists(0xc0018d2900) \t/home/vsts/work/1/s/ste/sender-azureFile.go:375 +0x119 github.com/Azure/azure-storage-azcopy/v10/ste.anyToRemotefolder({, _}, {{0xa1291151, 0x3187, 0x1b49, {0x55, 0xf, 0x8e, 0x31, 0x9b, ...}}, ...}, ...) \t/home/vsts/work/1/s/ste/xfer-anyToRemote-folder.go:70 +0x233 github.com/Azure/azure-storage-azcopy/v10/ste.anyToRemote({0x10379b8, 0xc0000fccb0}, {0xffe7e0, 0xc00128d540}, {0x7f6487d41a48, 0xc0003c8b80}, 0xc0004eb2c0, 0x2c) \t/home/vsts/work/1/s/ste/xfer-anyToRemote-file.go:183 +0x318 github.com/Azure/azure-storage-azcopy/v10/ste.parameterizeSend.func1({0x10379b8, 0xc0000fccb0}, {0xffe7e0, 0xc00128d540}, {0x7f6487d41a48, 0xc0003c8b80}) \t/home/vsts/work/1/s/ste/xfer.go:77 +0x44 github.com/Azure/azure-storage-azcopy/v10/ste.(jobPartMgr).StartJobXfer(0x1684020, {0x10379b8, 0xc0000fccb0}) \t/home/vsts/work/1/s/ste/mgr-JobPartMgr.go:715 +0x50 github.com/Azure/azure-storage-azcopy/v10/ste.(jobPartTransferMgr).StartJobXfer(0xc0000fccb0) \t/home/vsts/work/1/s/ste/mgr-JobPartTransferMgr.go:237 +0x32 github.com/Azure/azure-storage-azcopy/v10/ste.(jobMgr).transferProcessor.func1({0x10379b8, 0xc0000fccb0}) \t/home/vsts/work/1/s/ste/mgr-JobMgr.go:1015 +0x1b9 github.com/Azure/azure-storage-azcopy/v10/ste.(*jobMgr).transferProcessor(0xc00150a700, 0x10) \t/home/vsts/work/1/s/ste/mgr-JobMgr.go:1027 +0xc2 created by github.com/Azure/azure-storage-azcopy/v10/ste.NewJobMgr \t/home/vsts/work/1/s/ste/mgr-JobMgr.go:200 +0xbf4
2023/01/06 12:35:16 PERF: primary performance constraint is Unknown. States: X: 0, O: 0, M: 0, L: 0, R: 0, D: 0, W: 0, F: 0, B: 0, E: 0, T: 0, GRs: 128 2023/01/06 12:35:16 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 2023/01/06 12:35:18 PERF: primary performance constraint is Unknown. States: X: 0, O: 0, M: 0, L: 0, R: 0, D: 0, W: 0, F: 0, B: 0, E: 0, T: 0, GRs: 128 2023/01/06 12:35:18 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 2023/01/06 12:35:20 PERF: primary performance constraint is Unknown. States: X: 0, O: 0, M: 0, L: 0, R: 0, D: 0, W: 0, F: 0, B: 0, E: 0, T: 0, GRs: 128 2023/01/06 12:35:20 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 2023/01/06 12:35:22 PERF: primary performance constraint is Unknown. States: X: 0, O: 0, M: 0, L: 0, R: 0, D: 0, W: 0, F: 0, B: 0, E: 0, T: 0, GRs: 128 2023/01/06 12:35:22 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 2023/01/06 12:35:24 PERF: primary performance constraint is Unknown. States: X: 0, O: 0, M: 0, L: 0, R: 0, D: 0, W: 0, F: 0, B: 0, E: 0, T: 0, GRs: 128 2023/01/06 12:35:24 100.0 %, 0 Done, 0 Failed, 1 Pending, 1 Total, 2-sec Throughput (Mb/s): 0 2023/01/06 12:35:26 PERF: primary performance constraint is Unknown. States: X: 0, O: 0, M: