Duplicate "function.invoke.latency" logs

It looks like some of the logs in FunctionsMetrics table are duplicated (triplicated?) for Linux. Can you have someone take a look?

This is an issue for Analytics because we currently use FunctionsMetrics to determine invocation counts for functions. Looking at the FunctionsMetrics:
Execute: [Web] [Desktop] [Web (Lens)] [Desktop (SAW)] https://wawseus.kusto.windows.net/wawsprod
let StartDateTime = datetime(2019-07-11T00:00:00);
let EndDateTime = StartDateTime + 10m;
let app = 'ck-dlq-processing';
let fun = 'cleanDLQTrigger';
FunctionsMetrics
| where TIMESTAMP >= StartDateTime and TIMESTAMP < EndDateTime
| where EventName == "function.invoke.latency"
| where FunctionName == fun and AppName == app
| project PreciseTimeStamp, EventTimestamp, FluentdIngestTimestamp, EventName, Average, Count

  | PreciseTimeStamp | EventTimestamp | FluentdIngestTimestamp | EventName | Average | Count
-- | -- | -- | -- | -- | -- | --
  | 2019-07-11 00:00:18.0000000 | 07/11/2019 12:00:07.982 AM | 2019-07-11 00:00:18.0000000 | function.invoke.latency | 3073 | 2
  | 2019-07-11 00:00:18.0000000 | 07/11/2019 12:00:07.982 AM | 2019-07-11 00:00:18.0000000 | function.invoke.latency | 3073 | 2
  | 2019-07-11 00:00:18.0000000 | 07/11/2019 12:00:07.982 AM | 2019-07-11 00:00:18.0000000 | function.invoke.latency | 3073 | 2
  | 2019-07-11 00:00:48.0000000 | 07/11/2019 12:00:37.930 AM | 2019-07-11 00:00:48.0000000 | function.invoke.latency | 1893 | 12
  | 2019-07-11 00:00:48.0000000 | 07/11/2019 12:00:37.930 AM | 2019-07-11 00:00:48.0000000 | function.invoke.latency | 1893 | 12
  | 2019-07-11 00:00:48.0000000 | 07/11/2019 12:00:37.930 AM | 2019-07-11 00:00:48.0000000 | function.invoke.latency | 1893 | 12
  | 2019-07-11 00:01:18.0000000 | 07/11/2019 12:01:07.927 AM | 2019-07-11 00:01:18.0000000 | function.invoke.latency | 1801 | 11
  | 2019-07-11 00:01:18.0000000 | 07/11/2019 12:01:07.927 AM | 2019-07-11 00:01:18.0000000 | function.invoke.latency | 1801 | 11
  | 2019-07-11 00:01:18.0000000 | 07/11/2019 12:01:07.927 AM | 2019-07-11 00:01:18.0000000 | function.invoke.latency | 1801 | 11

Any updates? Here is a query to help identify mismatches between FunctionsLogs and FunctionsMetrics. (There are other issues that this query exposes too)

let StartDateTime = datetime(2019-07-17);
let EndDateTime = StartDateTime + 10m;
let FM =
FunctionsMetrics
| where TIMESTAMP >= StartDateTime and TIMESTAMP < EndDateTime
| where EventName == "function.invoke.latency"
| where FunctionName != ''
| summarize Invocations = sum(Count) by SubscriptionId, AppName, FunctionName, EventStampName;
let FL =
FunctionsLogs
| where TIMESTAMP >= StartDateTime and TIMESTAMP < EndDateTime
| where Summary startswith 'Executing'
| where FunctionName != ''
| summarize Invocations = count() by SubscriptionId, AppName, FunctionName, EventStampName;
FL
| join kind=fullouter FM on SubscriptionId, AppName, FunctionName, EventStampName
| extend SubscriptionId = coalesce(SubscriptionId, SubscriptionId1),
AppName = coalesce(AppName, AppName1),
FunctionName = coalesce(FunctionName, FunctionName1),
EventStampName=coalesce(EventStampName, EventStampName1)
| summarize IL = sum(Invocations), IM = sum(Invocations1) by SubscriptionId, AppName, FunctionName, EventStampName
| extend LogsMinusMetrics = IL - IM
| where LogsMinusMetrics !between ((-10) .. 10)

Yes I checked there are no changes on the functions runtime side in this codepath. I see this issue is happening since quite some time – I saw the first occurrence around 30 days ago which is the retention policy for our Kusto logs. Do you know when you first started seeing this issue?

I don’t know when this started. Analytics only ingests the minimum data needed, so we don’t have the FunctionsLogs data to do the comparison back in time.

I wonder if it would be helpful to add a self-serve alert to cover these sorts of situations?

Thanks Jason. I can try adding a self–serve alert for this. Can you please file an issue for this on Github and we can take a look at it?

Start with the supplied Kusto queries comparing FunctionsMetrics and FunctionsLogs, focusing on the repeated Linux function.invoke.latency rows. Trace the relevant metrics and logging entry points in the Azure Functions host; done means the duplication source is identified and invocation metrics no longer overcount.

Written by the indexing model from the issue text.