Adding function start time to metrics publisher (#4740)

divyagandhisethi · web-flow · commit a461f56b3b8e · 2019-08-01T12:39:32.000-07:00
* adding function start time to metrics publisher

* CR comments
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/MetricsEventManager.cs b/src/WebJobs.Script.WebHost/Diagnostics/MetricsEventManager.cs
@@ -481,7 +481,9 @@ private void RaiseFunctionMetricEvent(RunningFunctionInfo runningFunctionInfo, i
                         runningFunctionInfo.ExecutionStage.ToString(),
                         runningFunctionInfo.Success,
                         (long)executionTimespan,
-                        currentTime);
+                        _executionId,
+                        currentTime,
+                        runningFunctionInfo.StartTime);
                 }
             }
 
diff --git a/src/WebJobs.Script.WebHost/Metrics/IMetricsPublisher.cs b/src/WebJobs.Script.WebHost/Metrics/IMetricsPublisher.cs
@@ -8,6 +8,6 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Metrics
 {
     public interface IMetricsPublisher
     {
-        void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, DateTime utcNow);
+        void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, string executionId, DateTime eventTimeStamp, DateTime functionStartTime);
     }
 }
diff --git a/src/WebJobs.Script.WebHost/Metrics/LinuxContainerMetricsPublisher.cs b/src/WebJobs.Script.WebHost/Metrics/LinuxContainerMetricsPublisher.cs
@@ -95,17 +95,21 @@ private void OnStandbyOptionsChange()
             }
         }
 
-        public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, DateTime eventTimeStamp)
+        public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, string executionId, DateTime eventTimeStamp, DateTime functionStartTime)
         {
+            Enum.TryParse(executionStage, out FunctionExecutionStage functionExecutionStage);
+
             FunctionActivity activity = new FunctionActivity
             {
                 FunctionName = functionName,
                 InvocationId = invocationId,
                 Concurrency = concurrency,
-                ExecutionStage = executionStage,
+                ExecutionStage = functionExecutionStage,
+                ExecutionId = executionId,
                 IsSucceeded = success,
                 ExecutionTimeSpanInMs = executionTimeSpan,
                 EventTimeStamp = eventTimeStamp,
+                StartTime = functionStartTime,
                 Tenant = _tenant
             };
 
@@ -166,15 +170,14 @@ private async Task PublishActivity<T>(ConcurrentQueue<T> currentActivities, Bloc
             catch (Exception ex) when (!ex.IsFatal())
             {
                 _errorCount++;
-                _logger.LogError(ex, "Error publishing activites");
 
                 if (_errorCount < _maxErrorLimit)
                 {
                     _logger.LogWarning(ex, string.Format("Error count {0} within threshold. Will retry this batch later.", _errorCount));
                 }
                 else
                 {
-                    _logger.LogError(string.Format("LinuxContainerMetricsPublisher : Max error limit reached. Draining current activities for {0}", _containerName));
+                    _logger.LogError(ex, string.Format("LinuxContainerMetricsPublisher : Max error limit reached. Draining current activities for {0} for publish path: {1}", _containerName, publishPath));
                     DrainActivities(currentActivities, activitiesToProcess);
                     _errorCount = 0;
                 }
@@ -184,6 +187,7 @@ private async Task PublishActivity<T>(ConcurrentQueue<T> currentActivities, Bloc
         internal async Task SendRequest<T>(ConcurrentQueue<T> activitiesToPublish, string publishPath)
         {
             var request = BuildRequest(HttpMethod.Post, publishPath, activitiesToPublish.ToArray());
+            _logger.LogDebug($"Publishing {activitiesToPublish.Count()} activities to {publishPath}.");
             HttpResponseMessage response = await _httpClient.SendAsync(request);
             response.EnsureSuccessStatusCode();
         }
@@ -201,7 +205,7 @@ public void Start()
             _processMonitorTimer = new Timer(OnProcessMonitorTimer, null, TimeSpan.Zero, _memorySnapshotInterval);
             _metricsPublisherTimer = new Timer(OnFunctionMetricsPublishTimer, null, TimeSpan.Zero, _metricPublishInterval);
 
-            _logger.LogInformation(string.Format("Starting metrics publisher for container : {0}", _containerName));
+            _logger.LogInformation(string.Format("Starting metrics publisher for container : {0}. Publishing endpoint is {1}", _containerName, _requestUri));
         }
 
         private void OnProcessMonitorTimer(object state)
diff --git a/src/WebJobs.Script.WebHost/Models/ActivityBase.cs b/src/WebJobs.Script.WebHost/Models/ActivityBase.cs
@@ -2,9 +2,6 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
-using System.Collections.Generic;
-using System.Linq;
-using System.Threading.Tasks;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Models
 {
diff --git a/src/WebJobs.Script.WebHost/Models/FunctionActivity.cs b/src/WebJobs.Script.WebHost/Models/FunctionActivity.cs
@@ -2,9 +2,25 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Runtime.Serialization;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Models
 {
+    public enum FunctionExecutionStage
+    {
+        /// <summary>
+        /// The function is currently executing.
+        /// </summary>
+        [EnumMember]
+        InProgress,
+
+        /// <summary>
+        /// The function has finished executing.
+        /// </summary>
+        [EnumMember]
+        Finished
+    }
+
     public class FunctionActivity : ActivityBase
     {
         public string FunctionName { get; set; }
@@ -15,10 +31,12 @@ public class FunctionActivity : ActivityBase
 
         public string ExecutionId { get; set; }
 
-        public string ExecutionStage { get; set; }
+        public FunctionExecutionStage ExecutionStage { get; set; }
 
         public bool IsSucceeded { get; set; }
 
         public long ExecutionTimeSpanInMs { get; set; }
+
+        public DateTime StartTime { get; set; }
     }
 }
diff --git a/src/WebJobs.Script.WebHost/NullMetricsPublisher.cs b/src/WebJobs.Script.WebHost/NullMetricsPublisher.cs
@@ -17,9 +17,10 @@ public NullMetricsPublisher(ILogger<NullMetricsPublisher> logger)
             _logger.LogDebug("Initializing null metrics publisher");
         }
 
-        public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, DateTime utcNow)
+        public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, string executionId, DateTime eventTimeStamp, DateTime functionStartTime)
         {
-            _logger.LogDebug("Ignoring function activity metric: {functionName} {invocationId} {concurrency} {executionStage} {success} {executionTimeSpan}", functionName, invocationId, concurrency, executionStage, success, executionTimeSpan);
+            _logger.LogDebug("Ignoring function activity metric: {functionName} {invocationId} {concurrency} {executionStage} {success} {executionTimeSpan} {executionId} {eventTimeStamp} {functionStartTime}",
+                functionName, invocationId, concurrency, executionStage, success, executionTimeSpan, executionId, eventTimeStamp, functionStartTime);
         }
     }
 }
diff --git a/test/WebJobs.Script.Tests/Metrics/LinuxContainerMetricsPublisherTests.cs b/test/WebJobs.Script.Tests/Metrics/LinuxContainerMetricsPublisherTests.cs
@@ -33,7 +33,7 @@ public class LinuxContainerMetricsPublisherTests
             FunctionName = string.Empty,
             InvocationId = string.Empty,
             Concurrency = 1,
-            ExecutionStage = string.Empty,
+            ExecutionStage = FunctionExecutionStage.InProgress,
             IsSucceeded = true,
             ExecutionTimeSpanInMs = 1,
             EventTimeStamp = DateTime.UtcNow,
@@ -133,10 +133,12 @@ public void PublishFunctionActivity_SendsRequestHeaders()
                 _testFunctionActivity.FunctionName,
                 _testFunctionActivity.InvocationId,
                 _testFunctionActivity.Concurrency,
-                _testFunctionActivity.ExecutionStage,
+                _testFunctionActivity.ExecutionStage.ToString(),
                 _testFunctionActivity.IsSucceeded,
                 _testFunctionActivity.ExecutionTimeSpanInMs,
-                _testFunctionActivity.EventTimeStamp);
+                _testFunctionActivity.ExecutionId,
+                _testFunctionActivity.EventTimeStamp,
+                _testFunctionActivity.StartTime);
 
             Assert.Matches("Added function activity", _testLoggerProvider.GetAllLogMessages().Single().FormattedMessage);
             Assert.Equal(LogLevel.Debug, _testLoggerProvider.GetAllLogMessages().Single().Level);
@@ -145,7 +147,7 @@ public void PublishFunctionActivity_SendsRequestHeaders()
 
             _metricsPublisher.OnFunctionMetricsPublishTimer(null);
             _metricsPublisher.OnFunctionMetricsPublishTimer(null);
-            Assert.Empty(_testLoggerProvider.GetAllLogMessages());
+            Assert.Matches("Publishing", _testLoggerProvider.GetAllLogMessages().Single().FormattedMessage);
         }
 
         [Fact]
@@ -158,7 +160,7 @@ public void PublishMemoryActivity_SendsRequestHeaders()
 
             _metricsPublisher.OnFunctionMetricsPublishTimer(null);
             _metricsPublisher.OnFunctionMetricsPublishTimer(null);
-            Assert.Empty(_testLoggerProvider.GetLog());
+            Assert.Matches("Publishing", _testLoggerProvider.GetAllLogMessages().Single().FormattedMessage);
         }
 
         [Fact]

Original file line number	Diff line number	Diff line change
`@@ -481,7 +481,9 @@ private void RaiseFunctionMetricEvent(RunningFunctionInfo runningFunctionInfo, i`
`481`	`481`	`runningFunctionInfo.ExecutionStage.ToString(),`
`482`	`482`	`runningFunctionInfo.Success,`
`483`	`483`	`(long)executionTimespan,`
`484`		`- currentTime);`
	`484`	`+ _executionId,`
	`485`	`+ currentTime,`
	`486`	`+ runningFunctionInfo.StartTime);`
`485`	`487`	`}`
`486`	`488`	`}`
`487`	`489`
Original file line number	Diff line number	Diff line change
`@@ -8,6 +8,6 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Metrics`
`8`	`8`	`{`
`9`	`9`	`public interface IMetricsPublisher`
`10`	`10`	`{`
`11`		`- void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, DateTime utcNow);`
	`11`	`+ void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, string executionId, DateTime eventTimeStamp, DateTime functionStartTime);`
`12`	`12`	`}`
`13`	`13`	`}`
Original file line number	Diff line number	Diff line change
`@@ -95,17 +95,21 @@ private void OnStandbyOptionsChange()`
`95`	`95`	`}`
`96`	`96`	`}`
`97`	`97`
`98`		`- public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, DateTime eventTimeStamp)`
	`98`	`+ public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, string executionId, DateTime eventTimeStamp, DateTime functionStartTime)`
`99`	`99`	`{`
	`100`	`+ Enum.TryParse(executionStage, out FunctionExecutionStage functionExecutionStage);`
	`101`	`+`
`100`	`102`	`FunctionActivity activity = new FunctionActivity`
`101`	`103`	`{`
`102`	`104`	`FunctionName = functionName,`
`103`	`105`	`InvocationId = invocationId,`
`104`	`106`	`Concurrency = concurrency,`
`105`		`- ExecutionStage = executionStage,`
	`107`	`+ ExecutionStage = functionExecutionStage,`
	`108`	`+ ExecutionId = executionId,`
`106`	`109`	`IsSucceeded = success,`
`107`	`110`	`ExecutionTimeSpanInMs = executionTimeSpan,`
`108`	`111`	`EventTimeStamp = eventTimeStamp,`
	`112`	`+ StartTime = functionStartTime,`
`109`	`113`	`Tenant = _tenant`
`110`	`114`	`};`
`111`	`115`
`@@ -166,15 +170,14 @@ private async Task PublishActivity<T>(ConcurrentQueue<T> currentActivities, Bloc`
`166`	`170`	`catch (Exception ex) when (!ex.IsFatal())`
`167`	`171`	`{`
`168`	`172`	`_errorCount++;`
`169`		`- _logger.LogError(ex, "Error publishing activites");`
`170`	`173`
`171`	`174`	`if (_errorCount < _maxErrorLimit)`
`172`	`175`	`{`
`173`	`176`	`_logger.LogWarning(ex, string.Format("Error count {0} within threshold. Will retry this batch later.", _errorCount));`
`174`	`177`	`}`
`175`	`178`	`else`
`176`	`179`	`{`
`177`		`- _logger.LogError(string.Format("LinuxContainerMetricsPublisher : Max error limit reached. Draining current activities for {0}", _containerName));`
	`180`	`+ _logger.LogError(ex, string.Format("LinuxContainerMetricsPublisher : Max error limit reached. Draining current activities for {0} for publish path: {1}", _containerName, publishPath));`
`178`	`181`	`DrainActivities(currentActivities, activitiesToProcess);`
`179`	`182`	`_errorCount = 0;`
`180`	`183`	`}`
`@@ -184,6 +187,7 @@ private async Task PublishActivity<T>(ConcurrentQueue<T> currentActivities, Bloc`
`184`	`187`	`internal async Task SendRequest<T>(ConcurrentQueue<T> activitiesToPublish, string publishPath)`
`185`	`188`	`{`
`186`	`189`	`var request = BuildRequest(HttpMethod.Post, publishPath, activitiesToPublish.ToArray());`
	`190`	`+ _logger.LogDebug($"Publishing {activitiesToPublish.Count()} activities to {publishPath}.");`
`187`	`191`	`HttpResponseMessage response = await _httpClient.SendAsync(request);`
`188`	`192`	`response.EnsureSuccessStatusCode();`
`189`	`193`	`}`
`@@ -201,7 +205,7 @@ public void Start()`
`201`	`205`	`_processMonitorTimer = new Timer(OnProcessMonitorTimer, null, TimeSpan.Zero, _memorySnapshotInterval);`
`202`	`206`	`_metricsPublisherTimer = new Timer(OnFunctionMetricsPublishTimer, null, TimeSpan.Zero, _metricPublishInterval);`
`203`	`207`
`204`		`- _logger.LogInformation(string.Format("Starting metrics publisher for container : {0}", _containerName));`
	`208`	`+ _logger.LogInformation(string.Format("Starting metrics publisher for container : {0}. Publishing endpoint is {1}", _containerName, _requestUri));`
`205`	`209`	`}`
`206`	`210`
`207`	`211`	`private void OnProcessMonitorTimer(object state)`
Original file line number	Diff line number	Diff line change
`@@ -2,9 +2,6 @@`
`2`	`2`	`// Licensed under the MIT License. See License.txt in the project root for license information.`
`3`	`3`
`4`	`4`	`using System;`
`5`		`-using System.Collections.Generic;`
`6`		`-using System.Linq;`
`7`		`-using System.Threading.Tasks;`
`8`	`5`
`9`	`6`	`namespace Microsoft.Azure.WebJobs.Script.WebHost.Models`
`10`	`7`	`{`
Original file line number	Diff line number	Diff line change
`@@ -17,9 +17,10 @@ public NullMetricsPublisher(ILogger<NullMetricsPublisher> logger)`
`17`	`17`	`_logger.LogDebug("Initializing null metrics publisher");`
`18`	`18`	`}`
`19`	`19`
`20`		`- public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, DateTime utcNow)`
	`20`	`+ public void AddFunctionExecutionActivity(string functionName, string invocationId, int concurrency, string executionStage, bool success, long executionTimeSpan, string executionId, DateTime eventTimeStamp, DateTime functionStartTime)`
`21`	`21`	`{`
`22`		`- _logger.LogDebug("Ignoring function activity metric: {functionName} {invocationId} {concurrency} {executionStage} {success} {executionTimeSpan}", functionName, invocationId, concurrency, executionStage, success, executionTimeSpan);`
	`22`	`+ _logger.LogDebug("Ignoring function activity metric: {functionName} {invocationId} {concurrency} {executionStage} {success} {executionTimeSpan} {executionId} {eventTimeStamp} {functionStartTime}",`
	`23`	`+ functionName, invocationId, concurrency, executionStage, success, executionTimeSpan, executionId, eventTimeStamp, functionStartTime);`
`23`	`24`	`}`
`24`	`25`	`}`
`25`	`26`	`}`