Slow Australian NBN can’t handle the expectation
azcopy has about your bandwidth
I have been trying to copy a 1.7GB file to Azure blob storage container and it’s been failing. I’ve changed from Azure account login to a SAS URL and have started to investigate what is going on.
The upload to Azure kept failing because of
azcopy trying to send too many things down the pipe at once.
This is taken from Storage Explorers option to copy the azcopy command line and then edited to taste
export AZCOPY_CONCURRENCY_VALUE=2 export AZCOPY_CRED_TYPE=Anonymous; azcopy copy "/Users/jmcd/Downloads/ub3a.zip" "https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?sv=2018-03-28&ss=b&srt=sco&sp=rwdlac&se=2019-09-19T09%3A53%3A50Z&st=2019-09-19T01%3A53%3A50Z&spr=https&sig=<REDACTED>" --overwrite=false --follow-symlinks --recursive --from-to=LocalBlob --blob-type=BlockBlob --put-md5; unset AZCOPY_CRED_TYPE;
The answer is to change the AZCOPY_CONCURRENCY_VALUE I ended up using 4 and it was fine
What the azcopy job log said
The things I noticed in the log “HTTP request failed”, “context deadline exceeded” once you see debug output that mentions user directories it’s all down hill from the. Notice the (Try=8) I think that means azcopy has tried 8x to upload that block which makes sence since I was seeing masses more data being uploaded than was in the file. I saw “Try” up to Try=20 in the log so you can imagine how much extra, but wasted data that entailed.
PUT https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=mtu0zdc3mdutnzq1mc1kmjqxltq0zmmtmmjjogixztvlzdbk&comp=block&se=2019-09-21t14%3A07%3A32z&sig=-REDACTED-&sp=rwl&sr=c&sv=2018-03-28&timeout=901 Content-Length:  User-Agent: [AzCopy/10.2.1 Azure-Storage/0.7 (go1.12; darwin)] X-Ms-Client-Request-Id: [df195ca0-1246-49ec-7209-2607f70460e7] X-Ms-Version: [2018-03-28] 2019/09/18 15:41:21 ==> REQUEST/RESPONSE (Try=8/15m0.000575342s[SLOW >3s], OpTime=1h33m48.55610076s) -- REQUEST ERROR PUT https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=ywjmyzqxzditzdq4yi1mzdqxlty4mtitmtu2mmewyjexzwri&comp=block&se=2019-09-21t14%3A07%3A32z&sig=-REDACTED-&sp=rwl&sr=c&sv=2018-03-28&timeout=901 Content-Length:  User-Agent: [AzCopy/10.2.1 Azure-Storage/0.7 (go1.12; darwin)] X-Ms-Client-Request-Id: [6180cbd8-1dcd-49b6-73f0-7aee29630bb0] X-Ms-Version: [2018-03-28] -------------------------------------------------------------------------------- ERROR: -> github.com/Azure/azure-pipeline-go/pipeline.NewError, /Users/vsts/go/pkg/mod/github.com/!azure/[email protected]/pipeline/error.go:154 HTTP request failed Put https://tgnvhdstoracct.blob.core.windows.net/vhd1/ub3a.zip?blockid=YWJmYzQxZDItZDQ4Yi1mZDQxLTY4MTItMTU2MmEwYjExZWRi&comp=block&se=2019-09-21T14%3A07%3A32Z&sig=-REDACTED-&sp=rwl&sr=c&sv=2018-03-28&timeout=901: context deadline exceeded goroutine 102 [running]: github.com/Azure/azure-storage-azcopy/ste.stack(0xc000860e40, 0xc003b9c300, 0x0) /Users/vsts/agent/2.153.2/work/1/s/ste/xferLogPolicy.go:139 +0x9d github.com/Azure/azure-storage-azcopy/ste.NewRequestLogPolicyFactory.func1.1(0x487e840, 0xc001365f20, 0xc043978700, 0x10, 0x1, 0x0, 0xc007923ce0) /Users/vsts/agent/2.153.2/work/1/s/ste/xferLogPolicy.go:106 +0x662 github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc003cae0f0, 0x487e840, 0xc001365f20, 0xc043978700, 0xc007923d80, 0x0, 0x48706a0, 0x4097d26) /Users/vsts/go/pkg/mod/github.com/!azure/[email protected]/pipeline/core.go:43 +0x44 github.com/Azure/azure-storage-azcopy/ste.NewVersionPolicyFactory.func1.1(0x487e840, 0xc001365f20, 0xc043978700, 0xc000079000, 0x8, 0x203000, 0x203000) /Users/vsts/agent/2.153.2/work/1/s/ste/mgr-JobPartMgr.go:69 +0x1b2 github.com/Azure/azure-pipeline-go/pipeline.PolicyFunc.Do(0xc00081a0a0, 0x487e840, 0xc001365f20, 0xc043978700, 0x400e1f9, 0xc003e52aa0, 0x50, 0x48) /Users/vsts/go/pkg/mod/github.com/!azure/[email protected]/pipeline/core.go:43 +0x44 github.com/Azure/azure-storage-blob-go/azblob.responderPolicy.Do(0x4872160, 0xc00081a0a0, 0xc0000c9cc0, 0x487e840, 0xc001365f20, 0xc043
So far I have noted that my network monitor on Mac is saying that azcopy has only copied less than half the data… (Sent Bytes) This seems to be rising and falling so I’m not sure if the activity monitor is telling me pork pies or not.
Anyway seems like a fat pipe on a better network would be much better
Activity Monitor can help you know how much data each azcopy process has sent or received
Symptom of 100% appearing on an on-going Storage Explorer Transfer
However Storage Explorer is reporting 100%
Looking at the ingress on the storage account it’s kind of obvious that I’ve attempted to upload the file a number of times over in the last 24 hours. So Storage Explorer isn’t happy. Now I’m going to try raw azcopy and have tested a 180MB file and it works… So another 1.7GB and I’ll know if it’s just Storage Explorer or azcopy