Make MetricEvent.Completed more robust (#6973) (#6974)

Author: mathewc

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

@@ -79,18 +79,8 @@ public void EndEvent(object eventHandle)
             SystemMetricEvent evt = eventHandle as SystemMetricEvent;
             if (evt != null)
             {
-                long latencyMS = 0;
-                evt.StopWatch.Stop();
-                if (evt.StopWatch != null)
-                {
-                    evt.Duration = evt.StopWatch.Elapsed;
-                    latencyMS = evt.StopWatch.ElapsedMilliseconds;
-                }
-                else
-                {
-                    evt.Duration = DateTime.UtcNow - evt.Timestamp;
-                    latencyMS = (long)evt.Duration.TotalMilliseconds;
-                }
+                evt.Complete();
+                long latencyMS = (long)evt.Duration.TotalMilliseconds;
 
                 // event aggregation is based on this key
                 // for each unique key, there will be only 1
@@ -165,6 +155,7 @@ internal void FunctionStarted(FunctionStartedEvent startedEvent)
 
         internal void FunctionCompleted(FunctionStartedEvent completedEvent)
         {
+            completedEvent.Complete();
             _functionActivityTracker.FunctionCompleted(completedEvent);
         }
 

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

@@ -54,7 +54,6 @@ public void EndEvent(MetricEvent metricEvent)
         {
             if (metricEvent is FunctionStartedEvent completedEvent)
             {
-                completedEvent.Duration = DateTime.UtcNow - completedEvent.Timestamp;
                 _metricsEventManager.FunctionCompleted(completedEvent);
             }
             else

src/WebJobs.Script/Diagnostics/MetricEvent.cs

@@ -14,20 +14,29 @@ public abstract class MetricEvent
 
         public Stopwatch StopWatch { get; set; }
 
-        public TimeSpan Duration { get; set; }
+        public TimeSpan Duration { get; private set; }
 
         public string Data { get; set; }
 
         public string RuntimeSiteName { get; set; }
 
         public string SlotName { get; set; }
 
-        public bool Completed
+        public bool Completed { get; private set; }
+
+        public void Complete()
         {
-            get
+            if (StopWatch != null)
+            {
+                StopWatch.Stop();
+                Duration = StopWatch.Elapsed;
+            }
+            else
             {
-                return Duration != default(TimeSpan);
+                Duration = DateTime.UtcNow - Timestamp;
             }
+
+            Completed = true;
         }
     }
 }

test/WebJobs.Script.Tests.Integration/Diagnostics/MetricsEventManagerTests.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Reflection;
 using System.Text;
@@ -205,6 +206,52 @@ public void LogEvent_Function_AggregatesIntoExistingEvent()
             Assert.Null(metricEvent.FunctionName);
         }
 
+        [Fact]
+        public async Task Complete_TimestampSet_CompletesEvent()
+        {
+            var metadata = new FunctionMetadata();
+            var evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
+            evt.Timestamp = DateTime.UtcNow;
+            Assert.False(evt.Completed);
+
+            // complete immediately (potentially within system timer resolution)
+            evt.Complete();
+            Assert.True(evt.Completed);
+
+            evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
+            evt.Timestamp = DateTime.UtcNow;
+            Assert.False(evt.Completed);
+
+            // complete after a delay
+            await Task.Delay(250);
+            evt.Complete();
+            Assert.True(evt.Completed);
+        }
+
+        [Fact]
+        public async Task Complete_StopwatchSet_CompletesEvent()
+        {
+            var metadata = new FunctionMetadata();
+            var evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
+            evt.StopWatch = Stopwatch.StartNew();
+            Assert.False(evt.Completed);
+
+            // complete immediately (potentially within system timer resolution)
+            evt.Complete();
+            Assert.True(evt.Completed);
+            Assert.False(evt.StopWatch.IsRunning);
+
+            evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
+            evt.StopWatch = Stopwatch.StartNew();
+            Assert.False(evt.Completed);
+
+            // complete after a delay
+            await Task.Delay(250);
+            evt.Complete();
+            Assert.True(evt.Completed);
+            Assert.False(evt.StopWatch.IsRunning);
+        }
+
         [Fact]
         public void BeginEvent_ReturnsEventHandle()
         {