Duration in protocol of webconsole and in Table doesn't match

[Fabsi110]

Hi there,

I just started with Azure Functions and I am currently looking into execution times. When I invoke a Function directly from the webconsole for testing, the protocol under the code shows me the duration of that execution. When I look into the corresponding Table in my Storage Account I can find the execution Id related to the test I made in the webconsole. Unfortunately, the StartTime and EndTime in the Table doesn't match the duration in the protocol of the webconsole. If I go to the monitoring page the last invocations of that function are listed and here the duration matches the StartTime and EndTime I can see in the table, but it's again different from the duration from the protocol in the webconsole.

Is there a difference in how the protocol in the webconsole calculates the duration and how the monitoring / Table does it?

Investigative information

Please provide the following:

• Timestamp: 2017-07-15T22:30:27.929Z
• Invocation ID: 0907ee53-a088-487c-9b7d-045784449992
• Region: eu-west

Repro steps

Provide the steps required to reproduce the problem:

1. Create new Javascript Function / open existing one in developer webconsole
2. Execute Function with some kind of testdata
3. Note the duration the protocol is showing
4. Open the monitoring tab of that Function and note the duration that is displayed there
5. Check if there is a difference
6. [Optional] go into the storage account and look at the Table of the Function
7. [Optional] find the execution id and note the StartTime and EndTime and calculate the duration
8. [Optional] compare that duration with the duration from the protocol in the developer webconsole and from the monitoring tab (should be equal to monitoring tab, but not to the protocol)

Expected behavior

All three places where the duration of a Function is logged should have the same duration.

Actual behavior

The duration shown in the developer webconsole protocol doesn't match the duration in the monitoring tab and in the Table.

Known workarounds

I guess the correct duration is the one from the monitoring tab and from the Table, not that one from the developer webconsole protocol.

Related information

Provide any related information

• Programming language used: javascript
• Links to source: I just used the javascript that is auto-generated when a new Function is created

[paulbatum]

Can you include actual duration values to get an idea of how large the discrepancy is in your case?

The biggest cause of a gap in these times (can be on the order of seconds) occurs for C# functions, see here. But it shouldn't apply in this case since you're on JavaScript.

In the coming months our monitoring story will be switching over to default to using Application Insights. At a minimum, we want to make sure that the duration data presented in App Insights matches the duration emitted in the logs, so lets keep this issue open until we've confirmed that is the case.

[paulbatum]

Here's a quick example I got by testing myself with a javascript http trigger:

console logs: 2017-07-17T20:42:56.971 Function completed (Success, Id=b27cbe5a-b1f3-4261-a432-57f75510ef81, Duration=8ms)

app insights:

So in this case the delta was 1.423ms. The console could be rounding (since it never shows fractional milliseconds) but that still doesn't explain the difference.

[Fabsi110]

@paulbatum I made another run and received a delta of 48 ms.

console logs:

2017-07-18T21:11:46.311 Function completed (Success, Id=3f15c346-87e5-40d1-8ece-8fbcdc08fe05, Duration=2318ms)

And the monitor shows a duration of 2,366 ms.

[Fabsi110]

@paulbatum do you have any update on this?

[paulbatum]

No update - we have not spent any time looking into this difference yet.