Why the "runtimeStatus" in "statusQueryGetUri" not set immediately after timer is finished?

Question

Why the "runtimeStatus" is set to "Completed" only after 52 seconds not 30 as I set in context.CreateTimer() function when checking it with statusQueryGetUri http request?

The documentation that I used

My Code

 [FunctionName("H")]
            public static async Task<HttpResponseMessage> Start([HttpTrigger(AuthorizationLevel.Anonymous, "get","post",Route = "route/{route}")] HttpRequestMessage req, [DurableClient] IDurableOrchestrationClient client, string route) 
            {
                    string id = await client.StartNewAsync("Or1");
                    return client.CreateCheckStatusResponse(req, id);
               
            }
            [FunctionName("Or1")]
            public static async Task<string> Or1([OrchestrationTrigger] IDurableOrchestrationContext context, ILogger logger) 
            {
        
                using (CancellationTokenSource cts = new CancellationTokenSource()) 
                {
        
                    DateTime endTime = context.CurrentUtcDateTime.AddSeconds(30);
                    logger.LogInformation($"*********time now {context.CurrentUtcDateTime}");
                    logger.LogInformation($"*********end Time {endTime}");
        
                    await context.CreateTimer(endTime, cts.Token);
                    logger.LogInformation($"*********end Time finish {context.CurrentUtcDateTime}");
        
                    return "timer finished";
        
                }
            }
            [FunctionName("Activity1")]
            public static async Task A1([ActivityTrigger] IDurableActivityContext context) 
            {
                //Do something
            }

The Log

Functions:

        H: [GET,POST] http://localhost:7071/api/route/{route}

        Activity1: activityTrigger

        Or1: orchestrationTrigger

For detailed output, run func with --verbose flag.
[2021-01-13T16:17:06.841Z] Host lock lease acquired by instance ID '000000000000000000000000EB8F9C93'.
[2021-01-13T16:17:24.767Z] Executing 'H' (Reason='This function was programmatically called via the host APIs.', Id=0aeee0e1-6148-4c21-9aa9-d17a43bce8d1)
[2021-01-13T16:17:24.925Z] Executed 'H' (Succeeded, Id=0aeee0e1-6148-4c21-9aa9-d17a43bce8d1, Duration=164ms)
[2021-01-13T16:17:24.995Z] Executing 'Or1' (Reason='(null)', Id=6aa97b04-d526-41b1-9532-afb21c088b18)
[2021-01-13T16:17:25.006Z] *********time now 1/13/2021 4:17:24 PM
[2021-01-13T16:17:25.007Z] *********endTime 1/13/2021 4:17:54 PM
[2021-01-13T16:17:25.017Z] Executed 'Or1' (Succeeded, Id=6aa97b04-d526-41b1-9532-afb21c088b18, Duration=23ms)
[2021-01-13T16:18:16.476Z] Executing 'Or1' (Reason='(null)', Id=9749d719-5789-419a-908f-6523cf497cca)
[2021-01-13T16:18:16.477Z] *********time now 1/13/2021 4:17:24 PM
[2021-01-13T16:18:16.478Z] *********endTime 1/13/2021 4:17:54 PM
[2021-01-13T16:18:16.481Z] *********endTime finish 1/13/2021 4:18:16 PM
[2021-01-13T16:18:16.485Z] Executed 'Or1' (Succeeded, Id=9749d719-5789-419a-908f-6523cf497cca, Duration=9ms)

user1672994 · Answer 1 · 2021-01-14T05:35:02.430

The azure Orchestrater works on Queue polling which is implemented as a random exponential back-off algorithm to reduce the effect of idle-queue polling on storage transaction costs. When a message is found, the runtime immediately checks for another message; when no message is found, it waits for a period of time before trying again. After subsequent failed attempts to get a queue message, the wait time continues to increase until it reaches the maximum wait time, which defaults to 30 seconds.

If see your logs, you can notice that Orchestrater has triggered Timer at 16:17:24 and when it was finished at 16:17:54 a message was added in the storage queue. As mentioned above due to queue polling it seems that the message was picked at 16:18:16 to resume the orchestration execution.

I believe if you trigger the durable function multiple times then you will notice the total time to finish the orchestration would be different for each instance.

You can read about Azure function orchestration queue polling at here.

You can also check the history table to understand when a message was queued and when picked. Read about it at here.

To show how queuing works you can stop the function as soon timer is triggered. Following is the output in my local environment emulator queue which displays that a message is queued when timer is triggered

Now when Orchestrator function resumes again then it polls the message from queue and pick it to process further.

Note - in my local environment, I tried couple of time with your code as I noticed all instances finishes in ~30 secs.

Why the "runtimeStatus" in "statusQueryGetUri" not set immediately after timer is finished?

1 Answers1