Azure-functions-host: Blob triggered functions sometimes have a delay before being fired

[jaltin]

I am running into an issue with blob triggers taking long to fire. Hopefully you can help me with the information I have put together of my situation.

Background
I have a blob trigger function watching a container named 'imageuploads-new'.

I upload images into 'virtual folders' inside the container from a web page and the upload from the webpage goes very fast.

Problem
The problem I have is that very often when I upload the images into the container, most of them gets picked up by the blob trigger almost immediately but some of the images takes very long to be detected by the blob trigger (ranging from a few minutes to 30-40 minutes delay at worst).

A while back I was experiencing delays like this, and then I added a 'keep instance warm' timer triggered function that is called every 4 minutes (as per the recommendation of some users in other issues). At the time that seemed to have solved the problem with delays, but lately I have started to experience delays in blob triggers being fired again. This is causing big issues for me.

I have recreated examples of these delays and tried to give a trace of it so that someone at MS hopefully can figure out what is going wrong for me and help me to solve the issue.

Details about the function app

• C# class library that runs in version ~1.
• Runs under a consumption plan
• I don't want to share the function name publicly, but to help you find it indirectly, here is a function start call: 2018-12-07 15:57:55.489 Function started (Id=d66732f3-5e66-4926-97cd-6aeb4626db71). Location is north Europe.
• The function that listens to blob triggers is named 'ImageUploads_BlobTriggerNewImage'
• I use Application Insights tracing to be able to see when the blob trigger have been fired and to debug. I hope that you can access the application insights trace logs to extract more information?

Below are examples to illustrate where some of the uploaded images were processed after a delay. All times are as displayed as in the trace logs and are in my local time (UTC+1).

Example 1

• I added 111 small images (between 115-770kb) at 2018-12-07 12:52 to 'imageuploads-new/6078e80c-ab34-43d1-b078-47076c5f7621/[unique uuid for each image].jpg
• 110 of the 111 images had been detected by the blob trigger 12:52:35, so very fast
• The last image was detected by the blob trigger 12:58:40, a 6:05 minute delay compared to the other images
• All these entries can be found as trace logs in Application insights if you search for the string "ImageUploads_BlobTriggerNewImage fired for blob 'imageuploads-new/6078e80c-ab34-43d1-b078-47076c5f7621"

Example 2

• I added 111 small images (between 115-770kb) at 2018-12-07 12:57 to 'imageuploads-new/b6866bcf-995e-46da-a02a-2a80c0500c9c/[unique uuid for each image].jpg
• 102 of the 111 images had been detected by the blob trigger 12:58:09, so very fast
• The last 9 images were detected by the blob trigger 13:04:54, a 6:43 minute delay compared to the other images
• All these entries can be found as trace logs in Application insights if you search for the string "ImageUploads_BlobTriggerNewImage fired for blob 'imageuploads-new/b6866bcf-995e-46da-a02a-2a80c0500c9c"

Example 3

• I added 240 large images (between 5-8.8 mb in size) at 2018-12-07 15:22 to 'imageuploads-new/eb083d7b-7bb3-4243-8c8e-3245f6a49575/[unique uuid for each image].jpg
• These images took longer to finish uploading because of their size (about 4 minutes until last one), but blob triggering started very fast after the first images arrived in the container
• 238 of the 240 images had been detected by the blob trigger 15:24:27
• The last 2 images were detected by the blob trigger 15:26:31, a 2:04 minute delay compared to the other images
• All these entries can be found as trace logs in Application insights if you search for the string "ImageUploads_BlobTriggerNewImage fired for blob 'imageuploads-new/eb083d7b-7bb3-4243-8c8e-3245f6a49575"

Example 4

• I added 800 small images (between 44-98kb) at 2018-12-07 15:51 to 'imageuploads-new/9150ddce-bfdd-479c-a5f1-680168b1e216/[unique uuid for each image].jpg
• The upload went very fast, 56 seconds
• 786 of the 800 images had been detected by the blob trigger 15:53:27 (2:21 minutes in total from first to last)
• The last 14 images were detected by the blob trigger 15:57:51, a 4:24 minute delay compared to the other images
• All these entries can be found as trace logs in Application insights if you search for the string "ImageUploads_BlobTriggerNewImage fired for blob 'imageuploads-new/9150ddce-bfdd-479c-a5f1-680168b1e216"

[jaltin]

I initially posted this issue as a comment in issue #691 and @mathewc asked me to create a new issue for it. He also looked into the issue and made the following comment (thanks for this @mathewc!):

@jaltin I recommend you create a new issue with your details, since this is a closed issue about functions not being triggered at all. I was able to use the details you gave above to see some of the delays you mentioned in our system logs - e.g. a series of 111 blobs being processed all on the same worker instance with 110 of them all being processed in the first minute, but the last blob being started 6 minutes later. That delay was at 2018-12-07 11:52:37.530.

However, I do notice that at that time there are a lot of other blobs from other containers being processed by the same function at that time. So perhaps your issue is that you're expecting all the blobs for a particular folder upload to all be processed around the same time, but in reality the function is processing other container blobs at that time, increasing latency.

One suggestion: I'm not sure how resource intensive your function is, but if it is low, you could increase per instance parallelism by upping your queues BatchSize/NewBatchThreshold knobs. That would allow each instance to process more blobs in parallel.

@Mathew you are right that there are lot of other blogs from other containers being processed at the same time. The blog function trigger is the starting point for a number of functions being called in a sequence and the activity you see is a consequence of them being started from the blob trigger function.

Those other calls are not very resource intensive and they gets finished a long time before the last few blobs that are delayed gets processed, so I doubt that they are the culprit here. And also, as I mentioned in my initial posting, the issue seems to have arised lately. Earlier my "keep instance warm" functions seems to have solved it, but not any more. Perhaps something in the hosts runtime has changed lately?

Thanks!

[jaltin]

@mathewc, @davidebbo, do you have any ideas about what could cause this?

[jaltin]

Hi again @mathewc and @davidebbo.

I am still experiencing this problem regularly (in an app running in production) and I need to find a solution to it or consider alternatives because this is affecting us badly.

Can you or anyone else at Microsoft that works with Functions apps help me with this?

[nitingupta2012]

@mathewc and @davidebbo

We are also experiencing the same issue in our environment and affecting us badly on production. It takes minutes to trigger a single image blog upload event.

Kindly update if there is any solution to this problem.

[jaffadan]

I have moved to use Storage Events and no longer use Blob Triggers.

[BKB503]

@mathewc we are also having same issue in production, after restarting the function app it is picking up all the queued blob triggers, is some thing to memory issue? how can we diagnose this problem, function app is showing running status but not picking the blog triggers, please share your views

[jaltin]

Hi again @mathewc and @davidebbo (or anyone else at Microsoft that can help with this issue).

Still no update on this? Judging from other users comments it seems that this is a real issue and not just affecting our solution/implementation.

I would really appreciate it if you could have a look at this issue.

[davidebbo]

@jaltin just a note that I'm no longer at Microsoft, so I'll let others comment further.

[jaltin]

Thanks for the update @davidebbo.

Anyone else at Microsoft that can help with this? It's badly affecting us.

[yojagad]

@jaltin As mentioned https://docs.microsoft.com/en-us/azure/azure-functions/functions-bindings-storage-blob#trigger---polling , functions rely on logs to scan for new/changed blobs which could cause delays. Please try the recommendations posted there for faster and more reliable blob processing and let us know if you face any issues.