Emit function invocation latency events (#1030)

mathewc · mathewc · commit 2ab6f31afa75 · 2017-02-10T14:42:52.000-08:00
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/EventGenerator.cs b/src/WebJobs.Script.WebHost/Diagnostics/EventGenerator.cs
@@ -36,9 +36,9 @@ public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, strin
             }
         }
 
-        public void LogFunctionMetricEvent(string subscriptionId, string appName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp)
+        public void LogFunctionMetricEvent(string subscriptionId, string appName, string functionName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp)
         {
-            FunctionsSystemLogsEventSource.Instance.LogFunctionMetricEvent(subscriptionId, appName, eventName, average, minimum, maximum, count, ScriptHost.Version, eventTimestamp.ToString(EventTimestamp));
+            FunctionsSystemLogsEventSource.Instance.LogFunctionMetricEvent(subscriptionId, appName, functionName, eventName, average, minimum, maximum, count, ScriptHost.Version, eventTimestamp.ToString(EventTimestamp));
         }
 
         public void LogFunctionExecutionAggregateEvent(string siteName, string functionName, long executionTimeInMs, long functionStartedCount, long functionCompletedCount, long functionFailedCount)
@@ -132,11 +132,11 @@ public void RaiseFunctionsEventError(string SubscriptionId, string AppName, stri
             }
 
             [Event(65524, Level = EventLevel.Informational, Channel = EventChannel.Operational, Version = 1)]
-            public void LogFunctionMetricEvent(string SubscriptionId, string AppName, string EventName, long Average, long Minimum, long Maximum, long Count, string HostVersion, string EventTimestamp)
+            public void LogFunctionMetricEvent(string SubscriptionId, string AppName, string FunctionName, string EventName, long Average, long Minimum, long Maximum, long Count, string HostVersion, string EventTimestamp)
             {
                 if (IsEnabled())
                 {
-                    WriteEvent(65524, SubscriptionId, AppName, EventName, Average, Minimum, Maximum, Count, HostVersion, EventTimestamp);
+                    WriteEvent(65524, SubscriptionId, AppName, FunctionName, EventName, Average, Minimum, Maximum, Count, HostVersion, EventTimestamp);
                 }
             }
         }
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/IEventGenerator.cs b/src/WebJobs.Script.WebHost/Diagnostics/IEventGenerator.cs
@@ -10,7 +10,7 @@ public interface IEventGenerator
     {
         void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary, Exception exception = null);
 
-        void LogFunctionMetricEvent(string subscriptionId, string appName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp);
+        void LogFunctionMetricEvent(string subscriptionId, string appName, string functionName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp);
 
         void LogFunctionExecutionAggregateEvent(string siteName, string functionName, long executionTimeInMs, long functionStartedCount, long functionCompletedCount, long functionFailedCount);
 
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/MetricsEventManager.cs b/src/WebJobs.Script.WebHost/Diagnostics/MetricsEventManager.cs
@@ -47,7 +47,7 @@ public MetricsEventManager(ScriptSettingsManager settingsManager, IEventGenerato
         /// </summary>
         public ConcurrentDictionary<string, SystemMetricEvent> QueuedEvents { get; }
 
-        public object BeginEvent(string eventName)
+        public object BeginEvent(string eventName, string functionName = null)
         {
             if (string.IsNullOrEmpty(eventName))
             {
@@ -56,6 +56,7 @@ public object BeginEvent(string eventName)
 
             return new SystemMetricEvent
             {
+                FunctionName = functionName,
                 EventName = eventName.ToLowerInvariant(),
                 Timestamp = DateTime.UtcNow
             };
@@ -74,13 +75,19 @@ public void EndEvent(object eventHandle)
                 evt.Duration = DateTime.UtcNow - evt.Timestamp;
                 long latencyMS = (long)evt.Duration.TotalMilliseconds;
 
-                QueuedEvents.AddOrUpdate(evt.EventName,
+                // event aggregation is based on this key
+                // for each unique key, there will be only 1
+                // queued event that we aggregate into
+                string key = GetAggregateKey(evt.EventName, evt.FunctionName);
+
+                QueuedEvents.AddOrUpdate(key,
                     (name) =>
                     {
                         // create the default event that will be added
-                        // if an event isn't already queued for this event name
+                        // if an event isn't already queued for this key
                         return new SystemMetricEvent
                         {
+                            FunctionName = evt.FunctionName,
                             EventName = evt.EventName,
                             Minimum = latencyMS,
                             Maximum = latencyMS,
@@ -103,20 +110,22 @@ public void EndEvent(object eventHandle)
             }
         }
 
-        public void LogEvent(string eventName)
+        public void LogEvent(string eventName, string functionName = null)
         {
             if (string.IsNullOrEmpty(eventName))
             {
                 throw new ArgumentNullException(nameof(eventName));
             }
 
-            QueuedEvents.AddOrUpdate(eventName,
+            string key = GetAggregateKey(eventName, functionName);
+            QueuedEvents.AddOrUpdate(key,
                 (name) =>
                 {
                     // create the default event that will be added
-                    // if an event isn't already queued for this event name
+                    // if an event isn't already queued for this key
                     return new SystemMetricEvent
                     {
+                        FunctionName = functionName,
                         EventName = eventName.ToLowerInvariant(),
                         Count = 1
                     };
@@ -187,6 +196,18 @@ internal void HostStarted(ScriptHost scriptHost)
             }
         }
 
+        /// <summary>
+        /// Constructs the aggregate key used to group events. When metric events are
+        /// added for later aggregation on flush, they'll be grouped by this key.
+        /// </summary>
+        internal static string GetAggregateKey(string eventName, string functionName = null)
+        {
+            string key = string.IsNullOrEmpty(functionName) ?
+                eventName : $"{eventName}_{functionName}";
+
+            return key.ToLowerInvariant();
+        }
+
         private static string SerializeBindings(IEnumerable<BindingMetadata> bindings)
         {
             if (bindings != null)
@@ -247,6 +268,7 @@ protected internal virtual void WriteMetricEvents(SystemMetricEvent[] metricEven
                 _eventGenerator.LogFunctionMetricEvent(
                     subscriptionId,
                     appName,
+                    metricEvent.FunctionName ?? string.Empty,
                     metricEvent.EventName.ToLowerInvariant(),
                     metricEvent.Average,
                     metricEvent.Minimum,
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemMetricEvent.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemMetricEvent.cs
@@ -6,9 +6,23 @@
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
 {
-    [DebuggerDisplay("{EventName} {Count}")]
+    [DebuggerDisplay("{DebugValue,nq}")]
     public class SystemMetricEvent : MetricEvent
     {
+        private string DebugValue
+        {
+            get
+            {
+                string key = string.Empty;
+                if (!string.IsNullOrEmpty(FunctionName))
+                {
+                    key = $"Function: {FunctionName}, ";
+                }
+                key += $"Event: {EventName}, Count: {Count}";
+                return $"({key})";
+            }
+        }
+
         public string EventName { get; set; }
 
         public long Average { get; set; }
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/WebHostMetricsLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/WebHostMetricsLogger.cs
@@ -27,9 +27,9 @@ public WebHostMetricsLogger(ScriptSettingsManager settingsManager, IEventGenerat
             _metricsEventManager = new MetricsEventManager(settingsManager, eventGenerator, metricEventIntervalInSeconds);
         }
 
-        public object BeginEvent(string eventName)
+        public object BeginEvent(string eventName, string functionName = null)
         {
-            return _metricsEventManager.BeginEvent(eventName);
+            return _metricsEventManager.BeginEvent(eventName, functionName);
         }
 
         public void BeginEvent(MetricEvent metricEvent)
@@ -70,9 +70,9 @@ public void LogEvent(MetricEvent metricEvent)
             }
         }
 
-        public void LogEvent(string eventName)
+        public void LogEvent(string eventName, string functionName = null)
         {
-            _metricsEventManager.LogEvent(eventName);
+            _metricsEventManager.LogEvent(eventName, functionName);
         }
 
         protected virtual void Dispose(bool disposing)
diff --git a/src/WebJobs.Script.WebHost/GlobalSuppressions.cs b/src/WebJobs.Script.WebHost/GlobalSuppressions.cs
@@ -85,4 +85,6 @@
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "_httpConfiguration", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHooks.WebHookReceiverManager.#Dispose(System.Boolean)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2214:DoNotCallOverridableMethodsInConstructors", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.SecretManager.#.ctor(Microsoft.Azure.WebJobs.Script.WebHost.ISecretsRepository,Microsoft.Azure.WebJobs.Script.WebHost.IKeyValueConverterFactory,Microsoft.Azure.WebJobs.Host.TraceWriter,System.Boolean)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.DefaultSecretManagerFactory.#Create(Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager,Microsoft.Azure.WebJobs.Host.TraceWriter,Microsoft.Azure.WebJobs.Script.WebHost.ISecretsRepository)")]
-[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebScriptHostManager.#.ctor(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.WebHost.ISecretManagerFactory,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager,Microsoft.Azure.WebJobs.Script.WebHost.WebHostSettings,Microsoft.Azure.WebJobs.Script.IScriptHostFactory)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebScriptHostManager.#.ctor(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.WebHost.ISecretManagerFactory,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager,Microsoft.Azure.WebJobs.Script.WebHost.WebHostSettings,Microsoft.Azure.WebJobs.Script.IScriptHostFactory)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Performance", "CA1822:MarkMembersAsStatic", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.MetricsEventManager.#BeginEvent(System.String,System.String)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Performance", "CA1811:AvoidUncalledPrivateCode", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemMetricEvent.#DebugValue")]
diff --git a/src/WebJobs.Script/Description/FunctionInvokerBase.cs b/src/WebJobs.Script/Description/FunctionInvokerBase.cs
@@ -109,10 +109,9 @@ public async Task Invoke(object[] parameters)
 
             string invocationId = functionExecutionContext.InvocationId.ToString();
 
-            FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
+            var startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
             _metrics.BeginEvent(startedEvent);
-
-            LogInvocationMetrics(_metrics, Metadata.Bindings);
+            var invokeLatencyEvent = LogInvocationMetrics(_metrics, Metadata);
 
             try
             {
@@ -158,21 +157,25 @@ public async Task Invoke(object[] parameters)
                 {
                     _metrics.EndEvent(startedEvent);
                 }
+                if (invokeLatencyEvent != null)
+                {
+                    _metrics.EndEvent(invokeLatencyEvent);
+                }
             }
         }
 
-        internal static void LogInvocationMetrics(IMetricsLogger metrics, Collection<BindingMetadata> bindings)
+        internal static object LogInvocationMetrics(IMetricsLogger metrics, FunctionMetadata metadata)
         {
-            metrics.LogEvent(MetricEventNames.FunctionInvoke);
-
             // log events for each of the binding types used
-            foreach (var binding in bindings)
+            foreach (var binding in metadata.Bindings)
             {
                 string eventName = binding.IsTrigger ?
                     string.Format(MetricEventNames.FunctionBindingTypeFormat, binding.Type) :
                     string.Format(MetricEventNames.FunctionBindingTypeDirectionFormat, binding.Type, binding.Direction);
                 metrics.LogEvent(eventName);
             }
+
+            return metrics.BeginEvent(MetricEventNames.FunctionInvokeLatency, metadata.Name);
         }
 
         private void LogFunctionFailed(FunctionStartedEvent startedEvent, string resultString, string invocationId)
diff --git a/src/WebJobs.Script/Description/FunctionMetadata.cs b/src/WebJobs.Script/Description/FunctionMetadata.cs
@@ -47,7 +47,7 @@ public FunctionMetadata()
         /// </summary>
         public bool IsExcluded { get; set; }
 
-        public Collection<BindingMetadata> Bindings { get; private set; }
+        public Collection<BindingMetadata> Bindings { get; }
 
         public IEnumerable<BindingMetadata> InputBindings
         {
diff --git a/src/WebJobs.Script/Diagnostics/IMetricsLogger.cs b/src/WebJobs.Script/Diagnostics/IMetricsLogger.cs
@@ -13,8 +13,9 @@ public interface IMetricsLogger
         /// Begins an event.
         /// </summary>
         /// <param name="eventName">The event name.</param>
+        /// <param name="functionName">Optional function name for function specific events.</param>
         /// <returns>A handle to the event that was started.</returns>
-        object BeginEvent(string eventName);
+        object BeginEvent(string eventName, string functionName = null);
 
         /// <summary>
         /// Begins an event.
@@ -44,6 +45,7 @@ public interface IMetricsLogger
         /// Raises an event.
         /// </summary>
         /// <param name="eventName">The event name.</param>
-        void LogEvent(string eventName);
+        /// <param name="functionName">Optional function name for function specific events.</param>
+        void LogEvent(string eventName, string functionName = null);
     }
 }
diff --git a/src/WebJobs.Script/Diagnostics/MetricEvent.cs b/src/WebJobs.Script/Diagnostics/MetricEvent.cs
@@ -7,6 +7,8 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
 {
     public abstract class MetricEvent
     {
+        public string FunctionName { get; set; }
+
         public DateTime Timestamp { get; set; }
 
         public TimeSpan Duration { get; set; }
diff --git a/src/WebJobs.Script/Diagnostics/MetricEventNames.cs b/src/WebJobs.Script/Diagnostics/MetricEventNames.cs
@@ -10,7 +10,7 @@ public static class MetricEventNames
         public const string HostStartupLatency = "host.startup.latency";
 
         // function level events
-        public const string FunctionInvoke = "function.invoke";
+        public const string FunctionInvokeLatency = "function.invoke.latency";
         public const string FunctionBindingTypeFormat = "function.binding.{0}";
         public const string FunctionBindingTypeDirectionFormat = "function.binding.{0}.{1}";
         public const string FunctionCompileLatencyByLanguageFormat = "function.compile.{0}.latency";
diff --git a/src/WebJobs.Script/Diagnostics/MetricsLogger.cs b/src/WebJobs.Script/Diagnostics/MetricsLogger.cs
@@ -8,7 +8,7 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics
     /// </summary>
     public class MetricsLogger : IMetricsLogger
     {
-        public object BeginEvent(string eventName)
+        public object BeginEvent(string eventName, string functionName = null)
         {
             return null;
         }
@@ -29,7 +29,7 @@ public void LogEvent(MetricEvent metricEvent)
         {
         }
 
-        public void LogEvent(string eventName)
+        public void LogEvent(string eventName, string functionName = null)
         {
         }
     }
diff --git a/src/WebJobs.Script/Host/ScriptHost.cs b/src/WebJobs.Script/Host/ScriptHost.cs
@@ -89,7 +89,7 @@ public string InstanceId
             }
         }
 
-        public TraceWriter TraceWriter { get; private set; }
+        public TraceWriter TraceWriter { get; internal set; }
 
         public ScriptHostConfiguration ScriptConfig { get; private set; }
 
diff --git a/test/WebJobs.Script.Tests.Integration/CSharpEndToEndTests.cs b/test/WebJobs.Script.Tests.Integration/CSharpEndToEndTests.cs
@@ -9,7 +9,6 @@
 using System.Net.Http;
 using System.Net.Http.Headers;
 using System.Threading.Tasks;
-using System.Web.Http;
 using Microsoft.CodeAnalysis;
 using Microsoft.CodeAnalysis.CSharp;
 using Microsoft.WindowsAzure.Storage.Blob;
diff --git a/test/WebJobs.Script.Tests.Integration/Diagnostics/MetricsEventManagerTests.cs b/test/WebJobs.Script.Tests.Integration/Diagnostics/MetricsEventManagerTests.cs
diff --git a/test/WebJobs.Script.Tests.Integration/Host/ScriptHostManagerTests.cs b/test/WebJobs.Script.Tests.Integration/Host/ScriptHostManagerTests.cs
diff --git a/test/WebJobs.Script.Tests.Integration/Host/WebScriptHostManagerTests.cs b/test/WebJobs.Script.Tests.Integration/Host/WebScriptHostManagerTests.cs
diff --git a/test/WebJobs.Script.Tests/Description/FunctionInvokerBaseTests.cs b/test/WebJobs.Script.Tests/Description/FunctionInvokerBaseTests.cs

Original file line number	Diff line number	Diff line change
`@@ -36,9 +36,9 @@ public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, strin`
`36`	`36`	`}`
`37`	`37`	`}`
`38`	`38`
`39`		`- public void LogFunctionMetricEvent(string subscriptionId, string appName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp)`
	`39`	`+ public void LogFunctionMetricEvent(string subscriptionId, string appName, string functionName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp)`
`40`	`40`	`{`
`41`		`- FunctionsSystemLogsEventSource.Instance.LogFunctionMetricEvent(subscriptionId, appName, eventName, average, minimum, maximum, count, ScriptHost.Version, eventTimestamp.ToString(EventTimestamp));`
	`41`	`+ FunctionsSystemLogsEventSource.Instance.LogFunctionMetricEvent(subscriptionId, appName, functionName, eventName, average, minimum, maximum, count, ScriptHost.Version, eventTimestamp.ToString(EventTimestamp));`
`42`	`42`	`}`
`43`	`43`
`44`	`44`	`public void LogFunctionExecutionAggregateEvent(string siteName, string functionName, long executionTimeInMs, long functionStartedCount, long functionCompletedCount, long functionFailedCount)`
`@@ -132,11 +132,11 @@ public void RaiseFunctionsEventError(string SubscriptionId, string AppName, stri`
`132`	`132`	`}`
`133`	`133`
`134`	`134`	`[Event(65524, Level = EventLevel.Informational, Channel = EventChannel.Operational, Version = 1)]`
`135`		`- public void LogFunctionMetricEvent(string SubscriptionId, string AppName, string EventName, long Average, long Minimum, long Maximum, long Count, string HostVersion, string EventTimestamp)`
	`135`	`+ public void LogFunctionMetricEvent(string SubscriptionId, string AppName, string FunctionName, string EventName, long Average, long Minimum, long Maximum, long Count, string HostVersion, string EventTimestamp)`
`136`	`136`	`{`
`137`	`137`	`if (IsEnabled())`
`138`	`138`	`{`
`139`		`- WriteEvent(65524, SubscriptionId, AppName, EventName, Average, Minimum, Maximum, Count, HostVersion, EventTimestamp);`
	`139`	`+ WriteEvent(65524, SubscriptionId, AppName, FunctionName, EventName, Average, Minimum, Maximum, Count, HostVersion, EventTimestamp);`
`140`	`140`	`}`
`141`	`141`	`}`
`142`	`142`	`}`
Original file line number	Diff line number	Diff line change
`@@ -10,7 +10,7 @@ public interface IEventGenerator`
`10`	`10`	`{`
`11`	`11`	`void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary, Exception exception = null);`
`12`	`12`
`13`		`- void LogFunctionMetricEvent(string subscriptionId, string appName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp);`
	`13`	`+ void LogFunctionMetricEvent(string subscriptionId, string appName, string functionName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp);`
`14`	`14`
`15`	`15`	`void LogFunctionExecutionAggregateEvent(string siteName, string functionName, long executionTimeInMs, long functionStartedCount, long functionCompletedCount, long functionFailedCount);`
`16`	`16`
Original file line number	Diff line number	Diff line change
`@@ -27,9 +27,9 @@ public WebHostMetricsLogger(ScriptSettingsManager settingsManager, IEventGenerat`
`27`	`27`	`_metricsEventManager = new MetricsEventManager(settingsManager, eventGenerator, metricEventIntervalInSeconds);`
`28`	`28`	`}`
`29`	`29`
`30`		`- public object BeginEvent(string eventName)`
	`30`	`+ public object BeginEvent(string eventName, string functionName = null)`
`31`	`31`	`{`
`32`		`- return _metricsEventManager.BeginEvent(eventName);`
	`32`	`+ return _metricsEventManager.BeginEvent(eventName, functionName);`
`33`	`33`	`}`
`34`	`34`
`35`	`35`	`public void BeginEvent(MetricEvent metricEvent)`
`@@ -70,9 +70,9 @@ public void LogEvent(MetricEvent metricEvent)`
`70`	`70`	`}`
`71`	`71`	`}`
`72`	`72`
`73`		`- public void LogEvent(string eventName)`
	`73`	`+ public void LogEvent(string eventName, string functionName = null)`
`74`	`74`	`{`
`75`		`- _metricsEventManager.LogEvent(eventName);`
	`75`	`+ _metricsEventManager.LogEvent(eventName, functionName);`
`76`	`76`	`}`
`77`	`77`
`78`	`78`	`protected virtual void Dispose(bool disposing)`
Original file line number	Diff line number	Diff line change
`@@ -109,10 +109,9 @@ public async Task Invoke(object[] parameters)`
`109`	`109`
`110`	`110`	`string invocationId = functionExecutionContext.InvocationId.ToString();`
`111`	`111`
`112`		`- FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);`
	`112`	`+ var startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);`
`113`	`113`	`_metrics.BeginEvent(startedEvent);`
`114`		`-`
`115`		`- LogInvocationMetrics(_metrics, Metadata.Bindings);`
	`114`	`+ var invokeLatencyEvent = LogInvocationMetrics(_metrics, Metadata);`
`116`	`115`
`117`	`116`	`try`
`118`	`117`	`{`
`@@ -158,21 +157,25 @@ public async Task Invoke(object[] parameters)`
`158`	`157`	`{`
`159`	`158`	`_metrics.EndEvent(startedEvent);`
`160`	`159`	`}`
	`160`	`+ if (invokeLatencyEvent != null)`
	`161`	`+ {`
	`162`	`+ _metrics.EndEvent(invokeLatencyEvent);`
	`163`	`+ }`
`161`	`164`	`}`
`162`	`165`	`}`
`163`	`166`
`164`		`- internal static void LogInvocationMetrics(IMetricsLogger metrics, Collection<BindingMetadata> bindings)`
	`167`	`+ internal static object LogInvocationMetrics(IMetricsLogger metrics, FunctionMetadata metadata)`
`165`	`168`	`{`
`166`		`- metrics.LogEvent(MetricEventNames.FunctionInvoke);`
`167`		`-`
`168`	`169`	`// log events for each of the binding types used`
`169`		`- foreach (var binding in bindings)`
	`170`	`+ foreach (var binding in metadata.Bindings)`
`170`	`171`	`{`
`171`	`172`	`string eventName = binding.IsTrigger ?`
`172`	`173`	`string.Format(MetricEventNames.FunctionBindingTypeFormat, binding.Type) :`
`173`	`174`	`string.Format(MetricEventNames.FunctionBindingTypeDirectionFormat, binding.Type, binding.Direction);`
`174`	`175`	`metrics.LogEvent(eventName);`
`175`	`176`	`}`
	`177`	`+`
	`178`	`+ return metrics.BeginEvent(MetricEventNames.FunctionInvokeLatency, metadata.Name);`
`176`	`179`	`}`
`177`	`180`
`178`	`181`	`private void LogFunctionFailed(FunctionStartedEvent startedEvent, string resultString, string invocationId)`
Original file line number	Diff line number	Diff line change
`@@ -47,7 +47,7 @@ public FunctionMetadata()`
`47`	`47`	`/// </summary>`
`48`	`48`	`public bool IsExcluded { get; set; }`
`49`	`49`
`50`		`- public Collection<BindingMetadata> Bindings { get; private set; }`
	`50`	`+ public Collection<BindingMetadata> Bindings { get; }`
`51`	`51`
`52`	`52`	`public IEnumerable<BindingMetadata> InputBindings`
`53`	`53`	`{`
Original file line number	Diff line number	Diff line change
`@@ -7,6 +7,8 @@ namespace Microsoft.Azure.WebJobs.Script.Diagnostics`
`7`	`7`	`{`
`8`	`8`	`public abstract class MetricEvent`
`9`	`9`	`{`
	`10`	`+ public string FunctionName { get; set; }`
	`11`	`+`
`10`	`12`	`public DateTime Timestamp { get; set; }`
`11`	`13`
`12`	`14`	`public TimeSpan Duration { get; set; }`