(Shekhar) ETW Events Per Function execution

Author: mathewc

src/WebJobs.Script.WebHost/Diagnostics/MetricsEventManager.cs

@@ -2,40 +2,49 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Script;
 using Microsoft.Azure.WebJobs.Script.Description;
+using Microsoft.Azure.WebJobs.Script.Diagnostics;
 using Microsoft.Diagnostics.Tracing;
+using WebJobs.Script.WebHost.Models;
 
 namespace WebJobs.Script.WebHost.Diagnostics
 {
     public static class MetricsEventManager
     {        
         private static FunctionActivityTracker instance = null;
         private static object functionActivityTrackerLockObject = new object();
+        private static string siteName;
 
-        public static void FunctionStarted()
+        static MetricsEventManager()
+        {
+            siteName = GetNormalizedString(Environment.GetEnvironmentVariable("WEBSITE_SITE_NAME"));
+        }
+
+        public static void FunctionStarted(FunctionStartedEvent startedEvent)
         {
             lock (functionActivityTrackerLockObject)
             {
                 if (instance == null)
                 {
                     instance = new FunctionActivityTracker();
                 }
-                instance.FunctionStarted();
+                instance.FunctionStarted(startedEvent);
             }
         }
 
-        public static void FunctionCompleted()
+        public static void FunctionCompleted(FunctionStartedEvent completedEvent)
         {
             lock (functionActivityTrackerLockObject)
             {
                 if (instance != null)
                 {
-                    instance.FunctionCompleted();
+                    instance.FunctionCompleted(completedEvent);
                     if (!instance.IsActive)
                     {
                         instance.StopEtwTaskAndRaiseFinishedEvent();
@@ -52,7 +61,6 @@ public static void HostStarted(ScriptHost scriptHost)
                 return;
             }
 
-            var siteName = GetNormalizedString(Environment.GetEnvironmentVariable("WEBSITE_SITE_NAME"));
             foreach (var function in scriptHost.Functions)
             {
                 if (function == null || function.Metadata == null)
@@ -97,7 +105,9 @@ private class FunctionActivityTracker : IDisposable
             private DateTime startTime = DateTime.UtcNow;
             private ulong totalExecutionCount = 0;
             private ulong runningFunctionCount = 0;
+            private const int MetricEventIntervalInSeconds = 5;
             private CancellationTokenSource etwTaskcancellationSource = new CancellationTokenSource();
+            private ConcurrentQueue<FunctionMetrics> functionMetricsQueue = new ConcurrentQueue<FunctionMetrics>();
 
             internal FunctionActivityTracker()
             {
@@ -106,10 +116,18 @@ internal FunctionActivityTracker()
                     {
                         try
                         {
+                            int currentSecond = MetricEventIntervalInSeconds;
                             while (!etwTaskcancellationSource.Token.IsCancellationRequested)
                             {
-                                RaiseMetricEtwEvent(ExecutionStage.InProgress);
-                                await Task.Delay(TimeSpan.FromSeconds(5), etwTaskcancellationSource.Token);
+                                RaiseMetricsPerFunctionEvent();
+                                currentSecond = currentSecond + 1;
+                                if (currentSecond >= MetricEventIntervalInSeconds)
+                                {
+                                    RaiseMetricEtwEvent(ExecutionStage.InProgress);
+                                    currentSecond = 0;
+                                }
+
+                                await Task.Delay(TimeSpan.FromSeconds(1), etwTaskcancellationSource.Token);
                             }
                         }
                         catch (TaskCanceledException)
@@ -120,13 +138,7 @@ internal FunctionActivityTracker()
                     },
                     etwTaskcancellationSource.Token);
             }
-
-            private enum ExecutionStage
-            {
-                InProgress,
-                Finished
-            }
-
+            
             internal bool IsActive
             {
                 get
@@ -149,23 +161,33 @@ public void Dispose()
                 GC.SuppressFinalize(this);
             }
 
-           internal void FunctionStarted()
-           {
+            internal void FunctionStarted(FunctionStartedEvent startedEvent)
+            {
                 totalExecutionCount++;
                 runningFunctionCount++;
-           }
 
-            internal void FunctionCompleted()
+                var metricEventPerFunction = new FunctionMetrics(startedEvent.FunctionMetadata.Name, ExecutionStage.Started, 0);
+                functionMetricsQueue.Enqueue(metricEventPerFunction);
+            }
+
+            internal void FunctionCompleted(FunctionStartedEvent completedEvent)
             {
                 if (runningFunctionCount > 0)
                 {
                     runningFunctionCount--;
                 }
+
+                var functionStage = (completedEvent.Success == false) ? ExecutionStage.Failed : ExecutionStage.Succeeded;
+                long executionTimeInMS = (long)completedEvent.EndTime.Subtract(completedEvent.StartTime).TotalMilliseconds;
+
+                var monitoringEvent = new FunctionMetrics(completedEvent.FunctionMetadata.Name, functionStage, executionTimeInMS);
+                functionMetricsQueue.Enqueue(monitoringEvent);
             }
 
             internal void StopEtwTaskAndRaiseFinishedEvent()
             {
                 etwTaskcancellationSource.Cancel();
+                RaiseMetricsPerFunctionEvent();
                 RaiseMetricEtwEvent(ExecutionStage.Finished);
             }
 
@@ -180,6 +202,44 @@ private static void WriteFunctionsMetricEvent(string executionId, ulong executio
             {
                 MetricEventSource.Log.RaiseFunctionsMetricEvent(executionId, executionTimeSpan, executionCount, executionStage);
             }
+
+            private void RaiseMetricsPerFunctionEvent()
+            {
+                List<FunctionMetrics> metricsEventsList = GetMetricsQueueSnapshot();
+
+                var aggregatedEventsPerFunction = from item in metricsEventsList
+                                                  group item by item.FunctionName into FunctionGroups
+                                                  select new
+                                                  {
+                                                      FunctionName = FunctionGroups.Key,
+                                                      StartedCount = Convert.ToUInt64(FunctionGroups.Count(x => x.ExecutionStage == ExecutionStage.Started)),
+                                                      FailedCount = Convert.ToUInt64(FunctionGroups.Count(x => x.ExecutionStage == ExecutionStage.Failed)),
+                                                      SucceededCount = Convert.ToUInt64(FunctionGroups.Count(x => x.ExecutionStage == ExecutionStage.Succeeded)),
+                                                      TotalExectionTimeInMs = Convert.ToUInt64(FunctionGroups.Sum(x => Convert.ToDecimal(x.ExecutionTimeInMS)))
+                                                  };
+
+                foreach (var functionEvent in aggregatedEventsPerFunction)
+                {
+                    MetricEventSource.Log.RaiseMetricsPerFunctionEvent(siteName, functionEvent.FunctionName, functionEvent.TotalExectionTimeInMs, functionEvent.StartedCount, functionEvent.SucceededCount, functionEvent.FailedCount);
+                }
+            }
+
+            private List<FunctionMetrics> GetMetricsQueueSnapshot()
+            {
+                var queueSnapshot = new List<FunctionMetrics>();
+                var currentQueueLength = functionMetricsQueue.Count;
+
+                for (int iterator = 0; iterator < currentQueueLength; iterator++)
+                {
+                    FunctionMetrics queueItem;
+                    if (functionMetricsQueue.TryDequeue(out queueItem))
+                    {
+                        queueSnapshot.Add(queueItem);
+                    }
+                }
+
+                return queueSnapshot;
+            }
         }
 
         [EventSource(Guid = "08D0D743-5C24-43F9-9723-98277CEA5F9B")]
@@ -196,6 +256,15 @@ public void RaiseFunctionsMetricEvent(string executionId, ulong executionTimeSpa
                 }
             }
 
+            [Event(57907, Level = EventLevel.Informational, Channel = EventChannel.Operational)]
+            public void RaiseMetricsPerFunctionEvent(string siteName, string functionName, ulong executionTimeInMs, ulong functionStartedCount, ulong functionCompletedCount, ulong functionFailedCount)
+            {
+                if (IsEnabled())
+                {
+                    WriteEvent(57907, siteName, functionName, executionTimeInMs, functionStartedCount, functionCompletedCount, functionFailedCount);
+                }
+            }
+
             [Event(57908, Level = EventLevel.Informational, Channel = EventChannel.Operational)]
             public void RaiseFunctionsInfoEvent(string siteName, string functionName, string inputBindings, string outputBindings, string scriptType, bool isDisabled)
             {

src/WebJobs.Script.WebHost/Diagnostics/WebHostMetricsLogger.cs

@@ -14,17 +14,17 @@ public void BeginEvent(MetricEvent metricEvent)
             if (startedEvent != null)
             {
                 startedEvent.StartTime = DateTime.Now;
-                MetricsEventManager.FunctionStarted();
+                MetricsEventManager.FunctionStarted(startedEvent);
             }
         }
 
         public void EndEvent(MetricEvent metricEvent)
         {
-            FunctionStartedEvent startedEvent = metricEvent as FunctionStartedEvent;
-            if (startedEvent != null)
+            FunctionStartedEvent completedEvent = metricEvent as FunctionStartedEvent;
+            if (completedEvent != null)
             {
-                startedEvent.EndTime = DateTime.Now;
-                MetricsEventManager.FunctionCompleted();
+                completedEvent.EndTime = DateTime.Now;
+                MetricsEventManager.FunctionCompleted(completedEvent);
             }
         }
 

src/WebJobs.Script.WebHost/GlobalSuppressions.cs

@@ -20,3 +20,4 @@
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2227:CollectionPropertiesShouldBeReadOnly", Scope = "member", Target = "WebJobs.Script.WebHost.Models.FunctionStatus.#Errors")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "WebJobs.Script.WebHost.App_Start.AutofacBootstrap.#Initialize(Autofac.ContainerBuilder,WebJobs.Script.WebHost.WebHostSettings)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2227:CollectionPropertiesShouldBeReadOnly", Scope = "member", Target = "WebJobs.Script.WebHost.Models.HostStatus.#Errors")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Performance", "CA1810:InitializeReferenceTypeStaticFieldsInline", Scope = "member", Target = "WebJobs.Script.WebHost.Diagnostics.MetricsEventManager.#.cctor()")]

src/WebJobs.Script.WebHost/Models/FunctionMetrics.cs

@@ -0,0 +1,52 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+namespace WebJobs.Script.WebHost.Models
+{
+    public enum ExecutionStage
+    {
+        Started,
+        InProgress,
+        Finished,
+        Failed,
+        Succeeded
+    }
+
+    public class FunctionMetrics
+    {
+        private string _functionName;
+        private ExecutionStage _executionStage;
+        private long _executionTimeInMS;
+
+        public FunctionMetrics(string functionName, ExecutionStage executionStage, long executionTimeInMS)
+        {
+            _functionName = functionName;
+            _executionStage = executionStage;
+            _executionTimeInMS = executionTimeInMS;
+        }
+
+        public string FunctionName
+        {
+            get
+            {
+                return _functionName;
+            }
+        }
+
+        public ExecutionStage ExecutionStage
+        {
+            get
+            {
+                return _executionStage;
+            }
+        }
+
+        public long ExecutionTimeInMS
+        {
+            get
+            {
+                return _executionTimeInMS;
+            }
+        }
+    }
+}

src/WebJobs.Script.WebHost/WebJobs.Script.WebHost.csproj

@@ -294,6 +294,7 @@
     <Compile Include="Handlers\EnsureHostRunningHandler.cs" />
     <Compile Include="HostSecrets.cs" />
     <Compile Include="Models\FunctionInvocation.cs" />
+    <Compile Include="Models\FunctionMetrics.cs" />
     <Compile Include="Models\FunctionStatus.cs" />
     <Compile Include="Models\HostStatus.cs" />
     <Compile Include="Properties\AssemblyInfo.cs" />