Azure-storage-azcopy: Uploading large blob(s) using azcopy results in system level warnings

Created on 28 Jun 2019 · 24Comments · Source: Azure/azure-storage-azcopy

Which version of the AzCopy was used?

Note: The version is visible when running AzCopy without any argument

10.1.2

Which platform are you using? (ex: Windows, Mac, Linux)

Windows 10

What command did you run?

Note: Please remove the SAS to avoid exposing your credentials. If you cannot remember the exact command, please retrieve it from the beginning of the log file.

.azcopy.exe cp ".\ubuntu-18.04.2-desktop-amd64.iso" "https://**.blob.core.windows.net/*?" --log-level ERROR

What problem was encountered?

Many warnings shows up in the Event Viewer when trying to upload a large blob to a blob container:

The description for Event ID 0 from source C:\*****\azcopy.exe cannot be found. Either the component that raises this event is not installed on your local computer or the installation is corrupted. You can install or repair the component on the local computer.

If the event originated on another computer, the display information had to be saved with the event.

How can we reproduce the problem in the simplest way?

Upload a large (>100MB) blob to a blob container and you can then see the warnings in the Event Viewer. Additional info: small blobs doesn't have this issue.

Have you found a mitigation/solution?

No.

This relates to one of our customer's issue:
https://github.com/microsoft/AzureStorageExplorer/issues/1505

Could you please help us address this concern?
Thanks

Source

JasonYeMSFT

👍1

All 24 comments

My guess is that the warnings are appearing because the network bandwidth is slow, and so on big files, where the chunk size is automatically large, it takes longer than 3 seconds to upload one chunk. And so the warning gets logged.

@zezha-msft what do you think about us dropping the forced logging (to event log) of "slow" requests. Leaving the forced loggin to event log only happening for out-and-out errors?

JohnRusk on 4 Jul 2019

@JohnRusk Perhaps we could leave it on by default but provide a configuration to turn it off if needed, what do you think? I've logged this item in our backlog.

zezha-msft on 8 Jul 2019

It depends on what the original demand for "forced logging" was. If it was primarily "I want all _errors_ to be forced-logged" then I would suggest that logging of _slow things_ should not be forced by default. But if it was "I want all _errors_ and _slow things_ to be forced-logged" then leaving it on by default as you suggest would be better.

Maybe another option is to define the threshold for "slow" based on the chunk size... E.g. the current logging code has access to the HTTP headers, so could grab Content-Length, and dynamically adjust is
"slow" threshold. E.g. instead of being 3 seconds, it could be 3 seconds per 8 MB. What do you think @zezha-msft ?

JohnRusk on 8 Jul 2019

@JohnRusk I think that having the slow requests logged was part of the default logging requirement. The 3 seconds is to receive back the headers from the service, so it should indeed be adjusted for PUT calls.

zezha-msft on 9 Jul 2019

I'm about to create a PR to fix this. One question for you @zezha-msft … The change I'm doing affects the "tryDuration", but not the "operationDuration".

I think that's a little counter-intuitive (that it doesn't affect both) but on reflection I actually think its probably a good idea: operationDuration is the wall clock time from start of first try, encompassing any retries, and extending through to the end of Do. So for uploads it will include the time taken to write the body. Whereas tryDuration _now_ means "how long did we wait for Service to reply with headers, on this try?" TryDuration now does not include any body read or write time.

So you can get log lines like this for upload:

2019/07/16 02:10:11 ==> REQUEST/RESPONSE (Try=1/59ms, OpTime=41.9338358s) -- RESPONSE SUCCESSFULLY RECEIVED

In that example it took 41.19 seconds to upload the body (large body, slow network), but only 59ms for Service to reply with a success status after we finished transmitting the body.

Does that sound reasonable?

JohnRusk on 16 Jul 2019

@JohnRusk makes sense to me! :shipit:

zezha-msft on 17 Jul 2019

Fixed as above in version 10.3, which is now released.

JohnRusk on 11 Oct 2019

Hello, sorry, but problem is still exist.

AlexG7796 on 25 Oct 2019

@JohnRusk could you please follow up when time permits? Thanks!

zezha-msft on 25 Oct 2019

@AlexG7796 Thanks for bringing that to our attention, and for the informative screen shot. I see from the screenshot that it took a total of 13.9 seconds to upload the data chunk in question, of which 4.7 seconds was spent waiting for Blob Storage to reply. When working on this issue, we did not turn _off_ the logging of "slow" requests, we just changed the definition. "Slow" used to mean anything where the total time is over 3 seconds. Now it means anything where the service takes more that 3 seconds to respond _after we finish uploading the data_. That's what's happening in your case, and that's why its logging.

In your case:
(a) are you looking for a solution where it _never_ logs requests to the event log? (No matter how slow they are) or
(b) are you OK with it looking the occasional really slow request, but you don't want it logging as much as it did in your screenshot?

BTW, do you know roughly what your network bandwidth is? I'm wonder if that has influenced the logging frequency, by slowing down the replies from the Storage Service.

JohnRusk on 28 Oct 2019

👍1

@JohnRusk Thank you for your attention to my report.
I've started to use azCopy tool recently for uploading SQL backups to Storage, so I'm still learning, watching and tuning upload process. Backup uploads occur hourly and every time I have a big pile of files to upload. That is why event log completely flooded with such messages. I will be happy even with limiting of number of such messages. Currently, I would say, their numbers are too excessive.

Unfortunately I don't have numbers about network bandwidth, I'll try find out.

AlexG7796 on 29 Oct 2019

👍1

@AlexG7796 Any update on your network bandwidth?

JohnRusk on 15 Nov 2019

@AlexG7796 Any update on your network bandwidth?

Hi John. Network bandwight is around 4.3Gbps. AzCopy utilized all available bandwight.

AlexG7796 on 15 Nov 2019

Thanks. On that network, I'm surprised that it took long enough to trigger the logging threshold. We'll have to think about this a bit. Thanks for all the useful info.

JohnRusk on 15 Nov 2019

In your case:
(a) are you looking for a solution where it _never_ logs requests to the event log? (No matter how slow they are) or
(b) are you OK with it looking the occasional really slow request, but you don't want it logging as much as it did in your screenshot?

To chime in, I would recommend option (a) be possible - we already can consume the AZCopy log file; adding to the Event log doesn't provide any additional value and causes noise.

jeffwmiles on 10 Dec 2019

I had same events warnings and errors and as result it was impossible for me upload more than 40GB to Azure blob (always failed). When I throttled upload speed of azcopy (--cap-mbps 20) I was able to upload 127GB blob to Azure without prob;lems (only long time to upload).

Mi1an on 28 Jan 2020

@Mi1an Interesting. Do you know what you network bandwidth is?

JohnRusk on 28 Jan 2020

It sounds like your bandwidth is relatively low. Usually a better option than setting the cap is to set the environment variable AZCOPY_CONCURRENCY_VALUE to "AUTO". That usually gets closer to using your available bandwidth without creating too many connections.

JohnRusk on 28 Jan 2020

@JohnRusk My network bandwidth is 100Mb/s but there are other services and connections that are using this bandwidth mainly during day. In night it´s much better but it failed anyway.
Thanks for information, I will try to use that enviroment variable you wrote and I hope it will be working too.

Mi1an on 29 Jan 2020

Yes, that environment variable is ideal in your situation. Please let us know how it goes for you.

JohnRusk on 29 Jan 2020

@JohnRusk we are using the latest version azcopy 10.5.0 and we had cap the transfer rate to 250mbps, we are uploading aroun 40GB file.... we are still seeing this issue happening on our servers. please advice